Request with login privileges hangs for a specific user account, how to debug it?

[Lisandro]

Hi there! I'm having this weird problen and I can't figure out how to debug it, I was hoping you can help me.

When a user logs into my application, I set a cookie for the subdomain where the user is logged in and also I make the cookie valid for the main domain. 

This is working smoothly, we have **lots** of users working this way without any issue.

However, once in a time, some random user reports that server throws HTTP 504 after login. 

In all of those cases, I wasn't able to correct the problem, and I had to create a new account for the user and delete the old one with the problem.

I've verified, and the login is successful, but after that, any request made to an URL with login privileges just hangs and finally the webserver throws an HTTP 504 gateway timeout.

I can confirm that, when it happens, the problem affects only to the specific account (it's always a different one) while all the other users can work normally. 

When it happens, I can reproduce the problem if I try to impersonate that user account. The impersonation is made without problems, but then any other request from that account just hangs.

Today it happened again, and it's bothering me not being able to debug the problem.

Things I've tried:

 - deleting all the records in the web2py_session_* table

 - deleting all my cookies

What else can I do? I don't know exactly where to look, because there is no error ticket.

What could be the problem with the account that hangs and forces me to create a totally different new account?

Any comment or suggestion will be much apreciated.

Thanks in advance.

Regards,

Lisandro

[Leonel Câmara]

I would use redis for sessions instead of the default file based ones, it makes the site a lot quicker and it would probably solve your problem as I would bet this is happening due to a locked session file.

[Lisandro]

I store the sessions in the database, so there is no problem with a locked file.

I've just found something interesting that could help to figure out: when the problem presents, I checked the pg_stat_activity in postgres to see if there was a long running query, and there is indeed. But the query is a simple select to the auth_user table, to select the row of the logged in user. How can this query take that long? Does web2py lock the user row? If so, how do I release it?

Something to consider: in my db.py, at the end, I do this:

response.user = db.auth_user[auth.user.id] if auth.is_logged_in() else None

I think that is the query taking that long, because this is the SQL query that I can see in the pg_stat_activity:

SELECT  auth_user.id, auth_user.first_name, auth_user.last_name, auth_user.email, auth_user.password, auth_user.registration_key, auth_user.reset_password_key, auth_user.registration_id, auth_user.alta, auth_user.plantel, auth_user.responsable, auth_user.nombre, auth_user.telefono, auth_user.autor, auth_user.foto, auth_user.foto_temp, auth_user.moderador, auth_user.descripcion, auth_user.facebook, auth_user.twitter, auth_user.linkedin, auth_user.gplus FROM auth_user WHERE (auth_user.id = 2) LIMIT 1 OFFSET 0;

So, I think the problem is related to that sentence where I need to retrieve the row of the logged in user and store it in a variable inside response object.

What do you think?

[Anthony]

On Tuesday, April 3, 2018 at 8:43:31 AM UTC-4, Lisandro wrote:

I store the sessions in the database, so there is no problem with a locked file.

I've just found something interesting that could help to figure out: when the problem presents, I checked the pg_stat_activity in postgres to see if there was a long running query, and there is indeed. But the query is a simple select to the auth_user table, to select the row of the logged in user. How can this query take that long? Does web2py lock the user row? If so, how do I release it?

Something to consider: in my db.py, at the end, I do this:

response.user = db.auth_user[auth.user.id] if auth.is_logged_in() else None

FYI, auth.user is the user's record from db.auth_user (minus the password field and the update_record and delete_record attributes), so depending on what you are doing with response.user, you might be able to replace the above with:

response.user = auth.user

Or just use auth.user directly in your code.

Anthony

[Lisandro]

Thank you Anthony, yes I'm aware of that.

I use it like that for this reason: sometimes (not very often) an external app modifies a field of the auth_user table (specifically, it sets true or false a field that I use as a flag). However that change isn't updated to auth.user. In order to do so, the user needs to logout and login again. So I retrieve the auth_user record again and store it to response.answer.

Maybe it could be done like this:

if auth.is_logged_in():
    auth.user = db.auth_user[auth.user.id]

But I thought it could be break something with Auth methods, so I store it in response.user.

Anyway, I set this topic as "no action needed" because I opened a new topic, I've found some more info and I think the issue isn't related to that sentence. In fact, if it was related to that sentence, the problem would trigger with every user account. Today we just had two more of those cases. This is the new topic I posted:

https://groups.google.com/forum/#!topic/web2py/E9jrmf5E-B4

Regards,

Lisandro.

[Anthony]

On Thursday, April 5, 2018 at 2:57:20 PM UTC-4, Lisandro wrote:

Thank you Anthony, yes I'm aware of that.

I use it like that for this reason: sometimes (not very often) an external app modifies a field of the auth_user table (specifically, it sets true or false a field that I use as a flag). However that change isn't updated to auth.user. In order to do so, the user needs to logout and login again. So I retrieve the auth_user record again and store it to response.answer.

Maybe it could be done like this:

if auth.is_logged_in():
    auth.user = db.auth_user[auth.user.id]

But I thought it could be break something with Auth methods, so I store it in response.user.

Got it. Yeah, don't replace auth.user -- create a separate variable.

 

Anyway, I set this topic as "no action needed" because I opened a new topic, I've found some more info and I think the issue isn't related to that sentence.

But you indicated the select generated by that code was causing Postgres to hang. Are you sure that is the case? In other words, is the web2py code getting stuck at that line and ultimately causing your server to time out? Have you tried adding some logging statements to your code to determine exactly where it is getting stuck?

Anthony

[Lisandro]

Hi Anthony, again, thank you very much for your time, I really appreciate it.

To be truth, I'm not exactly sure that is the line where the code hangs, I supposed that because of the select query taking too long, but I can't be sure.

The problem is that the incident presents sporadically, and the worst part is that I can't reproduce it. Also, as it happens in the production server, I can't afford to modify the app code in production, giving that I would be making changes to an application that is used by our customers, so I'm in a tricky situation. 

I've made have plans to move sessions to Redis, but as a developer, I would still like to understand the root cause of the issue :)

Anyway, I'll wait to the incident happens again, hoping that it happens in an app of a "small" customer so I can do some tests.

 

Anthony

[Massimo Di Pierro]

That query itself cannot case hanging but maybe when that query is executed the database is busy with some other background task?
Try setting migrations to false. may be you are doing more database IO than you should

[Lisandro]

Hi Massimo, thank you for your time.

I had marked this thread as "no action needed" because I found the cause of the issue.

First I thought it was a different problem, so I opened a new thread in this forum:

https://groups.google.com/forum/#!topic/web2py/E9jrmf5E-B4

The title of that thread is not correct. I ended up finding that the problem is generated in some specific situations, and a specific key can't be stored at redis cache. In that thread I've posted some details about the tests I made to figure out that was the root cause. 

Sorry if I created some confusion opening a new thread, won't happen again :)