db.session.commit() is not performed at the end of requests (prev "Confirmation of users")

[lucanaso]

Update - begins
db.session.commit() is not performed automatically at the end of each request, despite having SQLALCHEMY_COMMIT_ON_TEARDOWN = True in config.py.
This issue was noted after analysing why user confirmation was not working properly.
The app is hosted on heroku (can be reached here), is using Heroku Postgres and is based on this repository, which is forked from the original 17d.
Update - ends

The confirmation link does not update the current_user.confirmed to True and new registered users thus remain unconfirmed.
If the model column is changed by hand via shell, then the user is recognised as confirmed and the app behaves as expected.

Here are the results of my analysis.
By examining the logs, the app behaviour is correct. I have the following lines from registration to confirmation of a new user:

1. REGISTER, GET, with status 200
   2015-08-07T08:50:09.059305+00:00 heroku[router]: at=info method=GET path="/auth/register"
2. REGISTER, POST, with status 302
   2015-08-07T08:50:23.954973+00:00 heroku[router]: at=info method=POST path="/auth/register"
3. LOGIN, GET, with status 200
   2015-08-07T08:50:24.181845+00:00 heroku[router]: at=info method=GET path="/auth/login"
4. (after clicking on the email confirmation link) CONFIRM, GET, with status 302
   2015-08-07T08:50:35.040888+00:00 heroku[router]: at=info method=GET path="/auth/confirm/eyJleHAiOjE0Mzg5NDEwMjMsImlhdCI6MTQzODkzNzQyMywiYWxnIjoiSFMyNTYifQ.eyJjb25maXJtIjoxfQ.7hMYjfDmmwE_8c3kkw7jSdIRLWV-bPSJCCuYsy7bPeY"
5. (login is required here) LOGIN GET, with status 200
   2015-08-07T08:50:35.259303+00:00 heroku[router]: at=info method=GET path="/auth/login?next=%2Fauth%2Fconfirm%2FeyJleHAiOjE0Mzg5NDEwMjMsImlhdCI6MTQzODkzNzQyMywiYWxnIjoiSFMyNTYifQ.eyJjb25maXJtIjoxfQ.7hMYjfDmmwE_8c3kkw7jSdIRLWV-bPSJCCuYsy7bPeY"
6. LOGIN POST, with status 302
   2015-08-07T08:51:04.677048+00:00 heroku[router]: at=info method=POST path="/auth/login?next=%2Fauth%2Fconfirm%2FeyJleHAiOjE0Mzg5NDEwMjMsImlhdCI6MTQzODkzNzQyMywiYWxnIjoiSFMyNTYifQ.eyJjb25maXJtIjoxfQ.7hMYjfDmmwE_8c3kkw7jSdIRLWV-bPSJCCuYsy7bPeY"
7. CONFIRM GET, with status 302
   2015-08-07T08:51:04.947112+00:00 heroku[router]: at=info method=GET path="/auth/confirm/eyJleHAiOjE0Mzg5NDEwMjMsImlhdCI6MTQzODkzNzQyMywiYWxnIjoiSFMyNTYifQ.eyJjb25maXJtIjoxfQ.7hMYjfDmmwE_8c3kkw7jSdIRLWV-bPSJCCuYsy7bPeY"
8. ROOT GET, with status 302
   2015-08-07T08:51:05.156445+00:00 heroku[router]: at=info method=GET path="/"
9. UNCONFIRMED , with status 200
   2015-08-07T08:51:05.868130+00:00 heroku[router]: at=info method=GET path="/auth/unconfirmed"

From what I understand, the auth.before_app_request is redirecting the user to the unconfirmed page.
However the flash message "You have confirmed your account. Thanks!" is displayed (see https://github.com/lucanaso/flasky/blob/master/app/auth/views.py#L72), therefore it looks like current_user.confirm returns True but it does not update the db (see https://github.com/lucanaso/flasky/blob/master/app/models.py#L147).

I have forked the project at commit 17d and after that I have committed only some files for deploying on heroku and requirements.

The app is running on heroku at: https://flasky-forky.herokuapp.com/ you can try it yourself by registering and trying to confirm.

What can be the cause of the user not being confirmed?

[chelseanderby]

I'm currently having a similar issue but a little bit different. I just got past Chapter 9 and now my confirmation emails only work if the user is already signed in. If the user is not already signed in, the confirmation email link just redirects to the login screen and asks the user to "Please log in to access this page." Of course, when the login they reach the unconfirmed page and can ask for a new email but that just seems rather unnecessary. I'm probably missing something rather stupid but I just can't seem to figure out why the confirmation emails only work if I'm already logged in. It's as if the confirm() function is getting skipped because of the @login_required. Everything else seems to work great.

[lucanaso]

@chelseanderby the login process is required by design. After you follow the confirmation link and login (if needed), you will see a flash message saying that the account is confirmed and you are then redirected to the home page. If the confirmation is not successful you will see a different flash message and still be redirected to the home page. By the way, I'd guess that in most of the cases (say when the confirmation email arrives immediately) the user is already logged in when they click on the link, because they were logged in to trigger the sending of the email.

If you are instead redirected to the auth/unconfirmed route then something is wrong, like in my case.

Let me add an important piece of information (I forgot to add that before, sorry). If I run the same application on localhost it works fine. The misbehaviour is only seen when the app runs on heroku.

[miguelgrinberg]

@lucanaso Are you using a Postgres database on Heroku, or something else?

[lucanaso]

@miguelgrinberg yes I am using "Heroku Postgres", plan "Hobby dev", version 9.4.4.
The application succeeds in writing to the database when creating a new user.
When running the app from shell, I can query the db and get the appropriate results. I can also commit changes.
If I explore the db from the Heroku web app, I can see that it has 6 tables and 8 records.

[miguelgrinberg]

Hmm. Have you made any changes to the configuration? In particular, the SQLALCHEMY_COMMIT_ON_TEARDOWN setting?

[lucanaso]

The SQLALCHEMY_COMMIT_ON_TEARDOWN is set to TRUE (see https://github.com/lucanaso/flasky/blob/master/config.py#L8).

I forked the latest available commit 17d from your repository,
then I changed the requirement files and added the Procfile. You can find the repository at https://github.com/lucanaso/flasky.
This is the only commit done after your latest 17d: lucanaso@93d83ea.

[chelseanderby]

@lucanaso Thanks for pointing that out to me. I guess that's just not how I'd imagine it would work because it seems a little counter intuitive to me that you would already need to be logged in earlier for the confirmation email to actually work (and from my workflow tests I did, the user would not be already logged in most cases since following the register path did not logged them automatically).

So I was wondering as to why when I login after the confirmation email link, I get directed to the unconfirmed page rather than the main page? Only when I am already logged in does the confirmation email work. I mean, I'd guess that's not how it's setup to work but if so, how could I change that? Of course, it's probably something I'm doing wrong, I just want to make sure I actually understand what the app is supposed to do because before I bash my head on the wall for awhile trying to figure it out because my app is almost identical at this stage, minus a couple changes.

EDIT: Figured it out. I'm not using Bootstrap for quick forms and I was setting up my form incorrectly so it was redirecting wrong.

[miguelgrinberg]

In theory it should not make a difference, but could you please try adding a db.session.commit() right after this line?

[lucanaso]

Indeed, it did not make any difference.

But here I need to ask a side question, before we validate this step.
I made this change on a new branch called flasky/bug/userconfirmation. For updating the application on heroku I then used the command:
git push heroku flasky/bug/userconfirmation(rather than git push heroku master)
followed by the usual heroku run python manage.py deploy and heroku restart.

Is this correct? or I have to push to master (which is the current default)? or I have to make the new branch as the default branch?

[lucanaso]

News update.

I have authenticated a user by hand and then experimented with it. In fact the application always fail to write to the db and gives no error message.

1. I submitted a new post, and it got lost. Nothing shows on main, nothing is written in the post table.
2. I updated my profile, and there was no sign of the changes, both on browser and on the fields in the user table for that user record.
3. I tried to change the password, and it didn't work.

It looks like only the user registration is actually working, which, I believe, is the only one to have an explicit db.session.commit().

Regarding the previous side note. I have made the latest branch as the default one and re-run the same commands as before, but still no difference.

[lucanaso]

It looks like the real problem behind this symptom is that db.session.commit() is not performed automatically at the end of each request.
I tested this with user confirmation and with password change, and the fix did work. I added a db.session.commit() here (models.py, for confirmation) and here (auth/views.py, for password change).

I did not see this before in #58 (comment) because the correct way to synch the heroku app to a branch different than master is:
git push heroku origin <your new branch>:master
so in this case:
git push heroku origin flasky/bug/userconfirmation:master

@miguelgrinberg @chelseanderby
I have updated this issue name and description. The question now is:
Why db.session.commit() is not performed automatically at the end of each request, despite using Heroku Postgres and having SQLALCHEMY_COMMIT_ON_TEARDOWN = True in config.py?

[alexli0707]

I met the same problem.
When I start with

python manage.py runserver

after every sql it log COMMIT.Everything goes fine.
When I start with

gunicorn manage:app

after every sql it log ROLLBACK. I thought in gunicorn SQLALCHEMY_COMMIT_ON_TEARDOWN=True not worked.

[coreybrett]

I just discovered this issue today.
Has anyone figured it out?

[miguelgrinberg]

Guys, I need you to tell me which version of gunicorn you are using.

With version 18.0 (the version that I used back when I created this application) everything works for me. With version 19.3 (the latest) I can reproduce the behavior described by @alexli0707 above.

Are you all using version 19? Can you try version 18 and let me know if this addresses the problem for you?

Thanks!

[coreybrett]

I have 19.3. I have not tried 18.0 yet.

[miguelgrinberg]

Okay, I think I have figured this thing out, turns out this is a Flask bug.

When the app context is popped at the end of the request, Flask calls all the @teardown_appcontext decorated callbacks. The auto commit feature of Flask-SQLAlchemy is implemented in one of these callbacks (code here). The teardown callbacks get one argument, which is an exception object if there was an error during the handling of the request.

Unfortunately, the logic that the current version of Flask uses to determine if there was an exception is flawed. This has been fixed in master (see the PR) and will be included in the 1.0 release.

Now, why this happens with gunicorn v19 but not v18? The sync worker in version 19 throws an exception before it passes control to the Flask application. This exception is handled, so it does not cause any problem other than exposing the Flask bug, which thinks this gunicorn exception was thrown during the request. So the Flask-SQLAlchemy teardown callback is called with the gunicorn exception as an argument, and because of that Flask-SQLAlchemy thinks there was an error and does not commit the session.

[coreybrett]

It appears this also prevents users from changing passwords in Flasky.
Does this mean we should just use gunicorn 18 for now until flask 1.0 is released?
Also, according to the docs for Flask-SQLAlchemy, "SQLALCHEMY_COMMIT_ON_TEARDOWN" is not recommended, should we just add commit lines to the effected functions?

[lucanaso]

I confirm that by using gunicorn 18.0 instead of gunicorn 19.3 (current latest) the issue is not present.
I have tested it with the confirmation case and the password change case. Both of them works fine and it is not required to add the commit at the end of the request.

Thanks to @miguelgrinberg for finding the solution and everyone else for contributing!

[mgraupner]

I guess this is the same issue @jeffjzx and I encountered over a year ago in #11 . My solution was to change the gunicorn worker to async but afterwards I changed it back to the normal sync worker (can't remember excactly why I did that...) and added an session.commit() to every line of my code where the db is touched. @miguelgrinberg Do you think there will be another Flask release given the last one was fom 2013? Otherwise it would probably be helpfull to mention the solution somewhere before even more people fall for this bug again.
I also don't think using gunicorn 18 is a good solution, there probably were some security fixes since the release of this version. Is there a WSGI server you personally would recommend instead of gunicorn @miguelgrinberg where this problem does not occur?

[xvweirong]

@miguelgrinberg @lucanaso This issue might be triggered by Flask-SSLify. I just confirmed that by using gunicorn 18.0 with Flask-SSLify 0.1.5 the issue is still there. Then I downgrade Flask-SSLify version to 0.1.4. Then the issue is not present.

[miguelgrinberg]

@xvweirong this is a Flask bug, it's already fixed in Flask's master branch. See pallets/flask#1393.

[ghost]

So I have downgraded my Gunicorn to version 18.0 by removing the most recent version and installing this one by pip install gunicorn==18.0. I still get the database problems where it doesn't look like its properly writing because the changes are not shown.

I am using https://www.digitalocean.com/community/tutorials/how-to-serve-flask-applications-with-gunicorn-and-nginx-on-ubuntu-14-04 to set up my app and everything works when I run gunicorn --bind 0.0.0.0:8000 wsgi however once I try to use the upstart script with nginx proxy requests, the database errors return.

Any ideas?

Edit: It seems adding db.session.commit() manually works, but I'm just wondering if anyone has found another way of doing this.

[miguelgrinberg]

My guess is that when you run through upstart you are not using the gunicorn installed in your virtualenv. Make sure you use the full path to the gunicorn executable, something like venv/bin/gunicorn instead of just gunicorn.

[fabionorcini]

Hi Miguel,

I can confirm that the bug also affects the version 18.0 of gunicorn:

Flask == 0.10.1
gunicorn == 18.0
SQLAlchemy == 0.9.7

With or without SSLfy, tested in different environments:

• heroku
• AWS (Debian)
• local (Mac OS X 10.11)

and several databases:

• mysql
• postgresql
• sqlite

In all these cases, the app seems to work properly (flash messages are displayed to the user) but the data is not (always) saved to DB.

Activating the echo of sqlalchemy I note that, in cases of failure to save on the db, a sqlalchemy rollaback is triggered.

The most disturbing thing is that all of the above occurs in almost randomly (!!!): the same views and request sometimes save the data and others do not .... I can not understand the cause of this random behavior.

The only workarond with these framework's versions appears to be the explicitly add db.session.commit () at the end of each request.

The alternative (form me) is to upgrade all the frameworks to the latest version:

Flask-SSLify == 0.1.5
gunicorn == 19.6.0
Flask == 0.11.1
SQLAlchemy == 1.0.13

Also in this case it seems that the random triggering of rollback are gone and the app seems to work properly.

I hope this information will be of help.

Greetings

[sachabest]

I am still having this issue on latest of all requirements. Does anyone know of a possible fix or workaround? I have echoing turned on and see rollbacks after almost every query (insert/select/whatever)

Edit: heroku postgres as well

[miguelgrinberg]

The workaround solution is to explicitly commit the database session at the end of each request. The auto-commit option in Flask-SQLAlchemy is not as reliable as I thought.

[sachabest]

Gotcha, thanks! It is also worth noting that I experienced the same rollback symptoms under the following circumstances:

• add an arbitrary item foo via db.session.add(foo)
• access some member variable of that item via foo.bar <-- causes a SELECT statement then a ROLLBACK
• call db.session.commit() <-- commits nothing as there was previously a rollback

I'm thinking this has something to do with heroku rather than any application/library logic? This just started happening an hour ago and the affected code has been static for a week or so.

@vincentdo this may be of relevance to you.

[mgraupner]

@sachabest @miguelgrinberg
What solved the issue for me was switching to uWSGI as the application server. Since then never had any problems with auto-commit and flask.

[miguelgrinberg]

Closing this issue, as it does not apply to the second edition of the book.