Flask-Sqlalchemy Missing BEGIN seems to cause out

2020-05-06 14:53发布

问题:

Update to my last question, please read this post for the background info. and This reddit thread for what I have tried. I have investigated further.

TL;DR is that for some requests I seem to get old data. I tested this by sending a POST to update an object and several GETs to print an attribute of that object. Usually the response is good, but every so often I get old data. This is a big problem when creating objects with relationships to other objects, the creation will fail if for some reason the foreign key object doesn't exist.

Example:

format@pixel:~$ curl -X POST https://example.com/app/region/rename/5/Old
Success
format@pixel:~$ curl -X POST https://example.com/app/region/rename/5/New
Success
format@pixel:~$ for i in {1..25}; do  echo ; curl -X GET https://example.com/app/region/name/5/; done
New
New
New
New
New
New
Old
New
New
New
New
New
New
New
New
New
New
New
New
New
New
New
New
New
New

I turned on SQLALCHEMY_ECHO and SQLALCHEMY_COMMIT_ON_TEARDOWN

app.config['SQLALCHEMY_ECHO'] = True
app.config['SQLALCHEMY_COMMIT_ON_TEARDOWN'] = True

And changed the code to print more info.

This first log snippet is typical for when the request is correct. You can see the implicit BEGIN and the COMMIT on teardown.

[Tue Jul 24 17:49:23.217666 2018] [wsgi:error] [pid 27919:tid 139730801542912] --- Get Start ---
[Tue Jul 24 17:49:23.219964 2018] [wsgi:error] [pid 27919:tid 139730801542912] 2018-07-24 17:49:23,219 INFO sqlalchemy.engine.base.Engine BEGIN (implicit)
[Tue Jul 24 17:49:23.220053 2018] [wsgi:error] [pid 27919:tid 139730801542912] INFO:sqlalchemy.engine.base.Engine:BEGIN (implicit)
[Tue Jul 24 17:49:23.221282 2018] [wsgi:error] [pid 27919:tid 139730801542912] 2018-07-24 17:49:23,221 INFO sqlalchemy.engine.base.Engine SELECT region.id AS region_id, region.name AS region_name, region.north AS region_north, region.west AS region_west, region.south AS region_south, region.east AS region_east, region.coords AS region_coords 
[Tue Jul 24 17:49:23.221321 2018] [wsgi:error] [pid 27919:tid 139730801542912] FROM region 
[Tue Jul 24 17:49:23.221336 2018] [wsgi:error] [pid 27919:tid 139730801542912] WHERE region.id = %s
[Tue Jul 24 17:49:23.221356 2018] [wsgi:error] [pid 27919:tid 139730801542912] 
[Tue Jul 24 17:49:23.221414 2018] [wsgi:error] [pid 27919:tid 139730801542912] INFO:sqlalchemy.engine.base.Engine:SELECT region.id AS region_id, region.name AS region_name, region.north AS region_north, region.west AS region_west, region.south AS region_south, region.east AS region_east, region.coords AS region_coords 
[Tue Jul 24 17:49:23.221433 2018] [wsgi:error] [pid 27919:tid 139730801542912] FROM region 
[Tue Jul 24 17:49:23.221447 2018] [wsgi:error] [pid 27919:tid 139730801542912] WHERE region.id = %s
[Tue Jul 24 17:49:23.221465 2018] [wsgi:error] [pid 27919:tid 139730801542912] 
[Tue Jul 24 17:49:23.221683 2018] [wsgi:error] [pid 27919:tid 139730801542912] 2018-07-24 17:49:23,221 INFO sqlalchemy.engine.base.Engine (5,)
[Tue Jul 24 17:49:23.221767 2018] [wsgi:error] [pid 27919:tid 139730801542912] INFO:sqlalchemy.engine.base.Engine:(5,)
[Tue Jul 24 17:49:23.222922 2018] [wsgi:error] [pid 27919:tid 139730801542912] 2018-07-24 17:49:23.222868 New
[Tue Jul 24 17:49:23.222990 2018] [wsgi:error] [pid 27919:tid 139730801542912] --- Get End ---
[Tue Jul 24 17:49:23.224867 2018] [wsgi:error] [pid 27919:tid 139730801542912] 2018-07-24 17:49:23,224 INFO sqlalchemy.engine.base.Engine COMMIT
[Tue Jul 24 17:49:23.224946 2018] [wsgi:error] [pid 27919:tid 139730801542912] INFO:sqlalchemy.engine.base.Engine:COMMIT

This next snippet is typical for when the request is incorrect. You can see it is performing the SELECT the same as before but, there is no BEGIN nor a COMMIT. Not sure what this means or why it occurs, but it leads me to believe the problem is in the SQLAlchemy or MySQL layer.

[Tue Jul 24 17:49:23.288116 2018] [wsgi:error] [pid 27919:tid 139730654033664] --- Get Start ---
[Tue Jul 24 17:49:23.290049 2018] [wsgi:error] [pid 27919:tid 139730654033664] 2018-07-24 17:49:23,289 INFO sqlalchemy.engine.base.Engine SELECT region.id AS region_id, region.name AS region_name, region.north AS region_north, region.west AS region_west, region.south AS region_south, region.east AS region_east, region.coords AS region_coords 
[Tue Jul 24 17:49:23.290079 2018] [wsgi:error] [pid 27919:tid 139730654033664] FROM region 
[Tue Jul 24 17:49:23.290092 2018] [wsgi:error] [pid 27919:tid 139730654033664] WHERE region.id = %s
[Tue Jul 24 17:49:23.290109 2018] [wsgi:error] [pid 27919:tid 139730654033664] 
[Tue Jul 24 17:49:23.290168 2018] [wsgi:error] [pid 27919:tid 139730654033664] INFO:sqlalchemy.engine.base.Engine:SELECT region.id AS region_id, region.name AS region_name, region.north AS region_north, region.west AS region_west, region.south AS region_south, region.east AS region_east, region.coords AS region_coords 
[Tue Jul 24 17:49:23.290186 2018] [wsgi:error] [pid 27919:tid 139730654033664] FROM region 
[Tue Jul 24 17:49:23.290197 2018] [wsgi:error] [pid 27919:tid 139730654033664] WHERE region.id = %s
[Tue Jul 24 17:49:23.290214 2018] [wsgi:error] [pid 27919:tid 139730654033664] 
[Tue Jul 24 17:49:23.290422 2018] [wsgi:error] [pid 27919:tid 139730654033664] 2018-07-24 17:49:23,290 INFO sqlalchemy.engine.base.Engine (5,)
[Tue Jul 24 17:49:23.290499 2018] [wsgi:error] [pid 27919:tid 139730654033664] INFO:sqlalchemy.engine.base.Engine:(5,)
[Tue Jul 24 17:49:23.291567 2018] [wsgi:error] [pid 27919:tid 139730654033664] 2018-07-24 17:49:23.291529 @@OLD@@
[Tue Jul 24 17:49:23.291591 2018] [wsgi:error] [pid 27919:tid 139730654033664] --- Get End ---

You can see by the timestamps that the good and bad requests are literally right after each other, there are several good requests after this bad one too, there seems to be no rhyme or reason.

I am using mysqlclient 1.3.13, SQLAlchemy 1.2.10, Flask-SQLAlchemy 2.3.2 and ran aapt-get upgrade earlier today.

回答1:

For reference if anyone finds this thread with the same issue, I fixed my problem.

My Flask App factory function had the line app.app_context().push() leftover from the early days when it was based off a Flask tutorial. During a restructuring of the project this line was left out and the problem fixed itself. Not sure why or how this line would cause this issue, and only for some but not all requests.