[web2py] Re: Possible bug? session.auth is None in some requests
do you think my problem of auth related?
https://groups.google.com/forum/?fromgroups=#!searchin/web2py/auth$20error/web2py/jkqyPM5_zaE/Ve5gy7greuoJ
i am running web2py on multi-threaded mod_wsgi
On Thursday, January 17, 2013 4:53:40 PM UTC+8, Daniel Gonzalez wrote:
>
> Yes Anthony, pretty sure. The little hash that you see in the logs *is*
> the cookie. Otherwise I can not grep for the relevant log messages (lots of
> activity going on with 10 parallel requests). This is the code that I have
> at the very top of my db.py:
>
> try:
> cookie_value = request.cookies[response.session_id_name].value
> except:
> cookie_value = None
>
> from gluon.tools import tools_tracer
> tools_tracer.setid(cookie_value)
>
> (tools_tracer is part of my instrumentation) And that setid call with
> compute a cookie hash for my logs.
>
> On Thursday, January 17, 2013 5:32:22 AM UTC+1, Anthony wrote:
>>
>> You're sure the client is sending the session cookie each time?
>>
>> On Wednesday, January 16, 2013 10:19:01 PM UTC-5, Daniel Gonzalez wrote:
>>>
>>> Hi,
>>>
>>> I am doing stress testing of my web2py application. The way I am doing
>>> this is:
>>>
>>>- 10 parallel clients
>>>- the clients log-in automatically, and obtain the session cookie
>>>- the clients log-in only *once* at the start of testing.
>>>- I use the session cookie to tag log messages in order to look for
>>>mý problem: this way I can relate the log messages to a specific client.
>>>- I am looking for problems in the web2py code, specifically in
>>>tools.py, Auth.__init__, where the auth.user is defined
>>>
>>> This is my instrumented code (in tools.py, Auth.__init__):
>>>
>>> if auth is None:
>>> tools_tracer.show('session.auth is None')
>>> if auth and auth.last_visit and auth.last_visit + \
>>> datetime.timedelta(days=0, seconds=auth.expiration) >request
>>> .now:
>>> tools_tracer.show('session.auth active, last_visit=%s', auth
>>> .last_visit)
>>> self.user = auth.user
>>> # this is a trick to speed up sessions
>>> if (request.now - auth.last_visit).seconds > (auth.expiration
>>> / 10):
>>> auth.last_visit = request.now
>>> else:
>>> self.user = None
>>> if session.auth:
>>> del session.auth
>>> tools_tracer.show('session.auth expired')
>>>
>>> And (in tools.py, Auth.login_user):
>>>
>>> current.session.auth = Storage(
>>> user = user,
>>> last_visit=current.request.now,
>>> expiration=self.settings.expiration,
>>> hmac_key=web2py_uuid())
>>> tools_tracer.show('session.auth created')
>>>
>>> This is my current log:
>>>
>>> 2013-01-17 04:00:41,816 - Thread-5 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:00:41,861 - Thread-5 - c2d769 session.auth
>>> created
>>> 2013-01-17 04:00:41,984 - Thread-6 - c2d769 session.auth
>>> active, last_visit=2013-01-17 04:00:41.791030
>>> 2013-01-17 04:00:48,923 - Thread-7 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:01:51,131 - Thread-10 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:01:51,214 - Thread-9 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:02:42,506 - Thread-6 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:04:42,791 - Thread-9 - c2d769 session.auth
>>> active, last_visit=2013-01-17 04:04:07.717197
>>> 2013-01-17 04:04:42,816 - Thread-4 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:04:48,862 - Thread-10 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:04:49,251 - Thread-6 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:05:35,713 - Thread-7 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:06:39,764 - Thread-8 - c2d769 session.auth
>>> active, last_visit=2013-01-17 04:06:10.853567
>>> 2013-01-17 04:06:39,803 - Thread-2 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:07:35,154 - Thread-8 - c2d769 session.auth
>>> active, last_visit=2013-01-17 04:07:00.261709
>>> 2013-01-17 04:07:40,860 - Thread-9 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:07:46,176 - Thread-8 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:07:46,266 - Thread-5 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:08:27,416 - Thread-9 - c2d769 session.auth
>>> active, last_visit=2013-01-17 04:08:03.492030
>>> 2013-01-17 04:08:27,436 - Thread-2 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:09:31,485 - Thread-10 - c2d769 session.auth
>>> is None
>>> 2013-01-17 04:11:21,903 - Thread-7 - c2d769 session.auth
>>> is None
>>> 2013-01-1
[web2py] Re: Possible bug? session.auth is None in some requests
Yes Anthony, pretty sure. The little hash that you see in the logs *is* the
cookie. Otherwise I can not grep for the relevant log messages (lots of
activity going on with 10 parallel requests). This is the code that I have
at the very top of my db.py:
try:
cookie_value = request.cookies[response.session_id_name].value
except:
cookie_value = None
from gluon.tools import tools_tracer
tools_tracer.setid(cookie_value)
(tools_tracer is part of my instrumentation) And that setid call with
compute a cookie hash for my logs.
On Thursday, January 17, 2013 5:32:22 AM UTC+1, Anthony wrote:
>
> You're sure the client is sending the session cookie each time?
>
> On Wednesday, January 16, 2013 10:19:01 PM UTC-5, Daniel Gonzalez wrote:
>>
>> Hi,
>>
>> I am doing stress testing of my web2py application. The way I am doing
>> this is:
>>
>>- 10 parallel clients
>>- the clients log-in automatically, and obtain the session cookie
>>- the clients log-in only *once* at the start of testing.
>>- I use the session cookie to tag log messages in order to look for
>>mý problem: this way I can relate the log messages to a specific client.
>>- I am looking for problems in the web2py code, specifically in
>>tools.py, Auth.__init__, where the auth.user is defined
>>
>> This is my instrumented code (in tools.py, Auth.__init__):
>>
>> if auth is None:
>> tools_tracer.show('session.auth is None')
>> if auth and auth.last_visit and auth.last_visit + \
>> datetime.timedelta(days=0, seconds=auth.expiration) >request
>> .now:
>> tools_tracer.show('session.auth active, last_visit=%s', auth.
>> last_visit)
>> self.user = auth.user
>> # this is a trick to speed up sessions
>> if (request.now - auth.last_visit).seconds > (auth.expiration
>> / 10):
>> auth.last_visit = request.now
>> else:
>> self.user = None
>> if session.auth:
>> del session.auth
>> tools_tracer.show('session.auth expired')
>>
>> And (in tools.py, Auth.login_user):
>>
>> current.session.auth = Storage(
>> user = user,
>> last_visit=current.request.now,
>> expiration=self.settings.expiration,
>> hmac_key=web2py_uuid())
>> tools_tracer.show('session.auth created')
>>
>> This is my current log:
>>
>> 2013-01-17 04:00:41,816 - Thread-5 - c2d769 session.auth
>> is None
>> 2013-01-17 04:00:41,861 - Thread-5 - c2d769 session.auth
>> created
>> 2013-01-17 04:00:41,984 - Thread-6 - c2d769 session.auth
>> active, last_visit=2013-01-17 04:00:41.791030
>> 2013-01-17 04:00:48,923 - Thread-7 - c2d769 session.auth
>> is None
>> 2013-01-17 04:01:51,131 - Thread-10 - c2d769 session.auth
>> is None
>> 2013-01-17 04:01:51,214 - Thread-9 - c2d769 session.auth
>> is None
>> 2013-01-17 04:02:42,506 - Thread-6 - c2d769 session.auth
>> is None
>> 2013-01-17 04:04:42,791 - Thread-9 - c2d769 session.auth
>> active, last_visit=2013-01-17 04:04:07.717197
>> 2013-01-17 04:04:42,816 - Thread-4 - c2d769 session.auth
>> is None
>> 2013-01-17 04:04:48,862 - Thread-10 - c2d769 session.auth
>> is None
>> 2013-01-17 04:04:49,251 - Thread-6 - c2d769 session.auth
>> is None
>> 2013-01-17 04:05:35,713 - Thread-7 - c2d769 session.auth
>> is None
>> 2013-01-17 04:06:39,764 - Thread-8 - c2d769 session.auth
>> active, last_visit=2013-01-17 04:06:10.853567
>> 2013-01-17 04:06:39,803 - Thread-2 - c2d769 session.auth
>> is None
>> 2013-01-17 04:07:35,154 - Thread-8 - c2d769 session.auth
>> active, last_visit=2013-01-17 04:07:00.261709
>> 2013-01-17 04:07:40,860 - Thread-9 - c2d769 session.auth
>> is None
>> 2013-01-17 04:07:46,176 - Thread-8 - c2d769 session.auth
>> is None
>> 2013-01-17 04:07:46,266 - Thread-5 - c2d769 session.auth
>> is None
>> 2013-01-17 04:08:27,416 - Thread-9 - c2d769 session.auth
>> active, last_visit=2013-01-17 04:08:03.492030
>> 2013-01-17 04:08:27,436 - Thread-2 - c2d769 session.auth
>> is None
>> 2013-01-17 04:09:31,485 - Thread-10 - c2d769 session.auth
>> is None
>> 2013-01-17 04:11:21,903 - Thread-7 - c2d769 session.auth
>> is None
>> 2013-01-17 04:12:20,207 - Thread-10 - c2d769 session.auth
>> is None
>>
>> (the c2d769 is a hash of the cookie, and identifies the client)
>>
>> As you can see, very often (for this specific client, other clients have
>> fewer problems), the session.auth is not there. But then suddenly, in the
>> following request, it is there again.
>>
>> What can be causing this strange problem?
[web2py] Re: Possible bug? session.auth is None in some requests
I was having a problem with session.auth.user, and my investigation has
narrowed down the problem to web2py code. Instrumenting the code has
allowed me to see the problem directly in the logs, but the problem is
there no matter whether I modify Auth code or not.
Sure, for me Sessions and session.auth work well ... except when I am doing
stress testing. With 10 parallel clients, I start to have problems. Strange
problems as you see in the logs: around 30% of the requests overall do not
have a properly initialized auth. Some clients have nearly no problems,
other clients have lots of problems.
My question is: is nobody else seeing this? Not even when running several
clients in parallel? I am fairly confident on my client code ...
I am running:
Version 2.4.1-alpha.2+timestamp.2013.01.13.13.14.47
commit 4bbe6ed, 4 days ago, "minor fix in parse_as_rest"
On Thursday, January 17, 2013 4:56:00 AM UTC+1, Massimo Di Pierro wrote:
>
> You are modifying Auth code. What problem are you trying to solve?
> Sessions and session.auth work well with both stable and trunk version, do
> they not?
>
> On Wednesday, 16 January 2013 21:19:01 UTC-6, Daniel Gonzalez wrote:
>>
>> Hi,
>>
>> I am doing stress testing of my web2py application. The way I am doing
>> this is:
>>
>>- 10 parallel clients
>>- the clients log-in automatically, and obtain the session cookie
>>- the clients log-in only *once* at the start of testing.
>>- I use the session cookie to tag log messages in order to look for
>>mý problem: this way I can relate the log messages to a specific client.
>>- I am looking for problems in the web2py code, specifically in
>>tools.py, Auth.__init__, where the auth.user is defined
>>
>> This is my instrumented code (in tools.py, Auth.__init__):
>>
>> if auth is None:
>> tools_tracer.show('session.auth is None')
>> if auth and auth.last_visit and auth.last_visit + \
>> datetime.timedelta(days=0, seconds=auth.expiration) >request
>> .now:
>> tools_tracer.show('session.auth active, last_visit=%s', auth.
>> last_visit)
>> self.user = auth.user
>> # this is a trick to speed up sessions
>> if (request.now - auth.last_visit).seconds > (auth.expiration
>> / 10):
>> auth.last_visit = request.now
>> else:
>> self.user = None
>> if session.auth:
>> del session.auth
>> tools_tracer.show('session.auth expired')
>>
>> And (in tools.py, Auth.login_user):
>>
>> current.session.auth = Storage(
>> user = user,
>> last_visit=current.request.now,
>> expiration=self.settings.expiration,
>> hmac_key=web2py_uuid())
>> tools_tracer.show('session.auth created')
>>
>> This is my current log:
>>
>> 2013-01-17 04:00:41,816 - Thread-5 - c2d769 session.auth
>> is None
>> 2013-01-17 04:00:41,861 - Thread-5 - c2d769 session.auth
>> created
>> 2013-01-17 04:00:41,984 - Thread-6 - c2d769 session.auth
>> active, last_visit=2013-01-17 04:00:41.791030
>> 2013-01-17 04:00:48,923 - Thread-7 - c2d769 session.auth
>> is None
>> 2013-01-17 04:01:51,131 - Thread-10 - c2d769 session.auth
>> is None
>> 2013-01-17 04:01:51,214 - Thread-9 - c2d769 session.auth
>> is None
>> 2013-01-17 04:02:42,506 - Thread-6 - c2d769 session.auth
>> is None
>> 2013-01-17 04:04:42,791 - Thread-9 - c2d769 session.auth
>> active, last_visit=2013-01-17 04:04:07.717197
>> 2013-01-17 04:04:42,816 - Thread-4 - c2d769 session.auth
>> is None
>> 2013-01-17 04:04:48,862 - Thread-10 - c2d769 session.auth
>> is None
>> 2013-01-17 04:04:49,251 - Thread-6 - c2d769 session.auth
>> is None
>> 2013-01-17 04:05:35,713 - Thread-7 - c2d769 session.auth
>> is None
>> 2013-01-17 04:06:39,764 - Thread-8 - c2d769 session.auth
>> active, last_visit=2013-01-17 04:06:10.853567
>> 2013-01-17 04:06:39,803 - Thread-2 - c2d769 session.auth
>> is None
>> 2013-01-17 04:07:35,154 - Thread-8 - c2d769 session.auth
>> active, last_visit=2013-01-17 04:07:00.261709
>> 2013-01-17 04:07:40,860 - Thread-9 - c2d769 session.auth
>> is None
>> 2013-01-17 04:07:46,176 - Thread-8 - c2d769 session.auth
>> is None
>> 2013-01-17 04:07:46,266 - Thread-5 - c2d769 session.auth
>> is None
>> 2013-01-17 04:08:27,416 - Thread-9 - c2d769 session.auth
>> active, last_visit=2013-01-17 04:08:03.492030
>> 2013-01-17 04:08:27,436 - Thread-2 - c2d769 session.auth
>> is None
>> 2013-01-17 04:09:31,485 - Thread-10 - c2d769 session.auth
>> is None
>> 2013-01-17 04:11:21,903 - Thread-7 - c2d76
[web2py] Re: Possible bug? session.auth is None in some requests
You're sure the client is sending the session cookie each time?
On Wednesday, January 16, 2013 10:19:01 PM UTC-5, Daniel Gonzalez wrote:
>
> Hi,
>
> I am doing stress testing of my web2py application. The way I am doing
> this is:
>
>- 10 parallel clients
>- the clients log-in automatically, and obtain the session cookie
>- the clients log-in only *once* at the start of testing.
>- I use the session cookie to tag log messages in order to look for mý
>problem: this way I can relate the log messages to a specific client.
>- I am looking for problems in the web2py code, specifically in
>tools.py, Auth.__init__, where the auth.user is defined
>
> This is my instrumented code (in tools.py, Auth.__init__):
>
> if auth is None:
> tools_tracer.show('session.auth is None')
> if auth and auth.last_visit and auth.last_visit + \
> datetime.timedelta(days=0, seconds=auth.expiration) >request
> .now:
> tools_tracer.show('session.auth active, last_visit=%s', auth.
> last_visit)
> self.user = auth.user
> # this is a trick to speed up sessions
> if (request.now - auth.last_visit).seconds > (auth.expiration
> / 10):
> auth.last_visit = request.now
> else:
> self.user = None
> if session.auth:
> del session.auth
> tools_tracer.show('session.auth expired')
>
> And (in tools.py, Auth.login_user):
>
> current.session.auth = Storage(
> user = user,
> last_visit=current.request.now,
> expiration=self.settings.expiration,
> hmac_key=web2py_uuid())
> tools_tracer.show('session.auth created')
>
> This is my current log:
>
> 2013-01-17 04:00:41,816 - Thread-5 - c2d769 session.auth
> is None
> 2013-01-17 04:00:41,861 - Thread-5 - c2d769 session.auth
> created
> 2013-01-17 04:00:41,984 - Thread-6 - c2d769 session.auth
> active, last_visit=2013-01-17 04:00:41.791030
> 2013-01-17 04:00:48,923 - Thread-7 - c2d769 session.auth
> is None
> 2013-01-17 04:01:51,131 - Thread-10 - c2d769 session.auth
> is None
> 2013-01-17 04:01:51,214 - Thread-9 - c2d769 session.auth
> is None
> 2013-01-17 04:02:42,506 - Thread-6 - c2d769 session.auth
> is None
> 2013-01-17 04:04:42,791 - Thread-9 - c2d769 session.auth
> active, last_visit=2013-01-17 04:04:07.717197
> 2013-01-17 04:04:42,816 - Thread-4 - c2d769 session.auth
> is None
> 2013-01-17 04:04:48,862 - Thread-10 - c2d769 session.auth
> is None
> 2013-01-17 04:04:49,251 - Thread-6 - c2d769 session.auth
> is None
> 2013-01-17 04:05:35,713 - Thread-7 - c2d769 session.auth
> is None
> 2013-01-17 04:06:39,764 - Thread-8 - c2d769 session.auth
> active, last_visit=2013-01-17 04:06:10.853567
> 2013-01-17 04:06:39,803 - Thread-2 - c2d769 session.auth
> is None
> 2013-01-17 04:07:35,154 - Thread-8 - c2d769 session.auth
> active, last_visit=2013-01-17 04:07:00.261709
> 2013-01-17 04:07:40,860 - Thread-9 - c2d769 session.auth
> is None
> 2013-01-17 04:07:46,176 - Thread-8 - c2d769 session.auth
> is None
> 2013-01-17 04:07:46,266 - Thread-5 - c2d769 session.auth
> is None
> 2013-01-17 04:08:27,416 - Thread-9 - c2d769 session.auth
> active, last_visit=2013-01-17 04:08:03.492030
> 2013-01-17 04:08:27,436 - Thread-2 - c2d769 session.auth
> is None
> 2013-01-17 04:09:31,485 - Thread-10 - c2d769 session.auth
> is None
> 2013-01-17 04:11:21,903 - Thread-7 - c2d769 session.auth
> is None
> 2013-01-17 04:12:20,207 - Thread-10 - c2d769 session.auth
> is None
>
> (the c2d769 is a hash of the cookie, and identifies the client)
>
> As you can see, very often (for this specific client, other clients have
> fewer problems), the session.auth is not there. But then suddenly, in the
> following request, it is there again.
>
> What can be causing this strange problem?
>
> Thanks,
> Daniel
>
>
--
[web2py] Re: Possible bug? session.auth is None in some requests
You are modifying Auth code. What problem are you trying to solve? Sessions
and session.auth work well with both stable and trunk version, do they not?
On Wednesday, 16 January 2013 21:19:01 UTC-6, Daniel Gonzalez wrote:
>
> Hi,
>
> I am doing stress testing of my web2py application. The way I am doing
> this is:
>
>- 10 parallel clients
>- the clients log-in automatically, and obtain the session cookie
>- the clients log-in only *once* at the start of testing.
>- I use the session cookie to tag log messages in order to look for mý
>problem: this way I can relate the log messages to a specific client.
>- I am looking for problems in the web2py code, specifically in
>tools.py, Auth.__init__, where the auth.user is defined
>
> This is my instrumented code (in tools.py, Auth.__init__):
>
> if auth is None:
> tools_tracer.show('session.auth is None')
> if auth and auth.last_visit and auth.last_visit + \
> datetime.timedelta(days=0, seconds=auth.expiration) >request
> .now:
> tools_tracer.show('session.auth active, last_visit=%s', auth.
> last_visit)
> self.user = auth.user
> # this is a trick to speed up sessions
> if (request.now - auth.last_visit).seconds > (auth.expiration
> / 10):
> auth.last_visit = request.now
> else:
> self.user = None
> if session.auth:
> del session.auth
> tools_tracer.show('session.auth expired')
>
> And (in tools.py, Auth.login_user):
>
> current.session.auth = Storage(
> user = user,
> last_visit=current.request.now,
> expiration=self.settings.expiration,
> hmac_key=web2py_uuid())
> tools_tracer.show('session.auth created')
>
> This is my current log:
>
> 2013-01-17 04:00:41,816 - Thread-5 - c2d769 session.auth
> is None
> 2013-01-17 04:00:41,861 - Thread-5 - c2d769 session.auth
> created
> 2013-01-17 04:00:41,984 - Thread-6 - c2d769 session.auth
> active, last_visit=2013-01-17 04:00:41.791030
> 2013-01-17 04:00:48,923 - Thread-7 - c2d769 session.auth
> is None
> 2013-01-17 04:01:51,131 - Thread-10 - c2d769 session.auth
> is None
> 2013-01-17 04:01:51,214 - Thread-9 - c2d769 session.auth
> is None
> 2013-01-17 04:02:42,506 - Thread-6 - c2d769 session.auth
> is None
> 2013-01-17 04:04:42,791 - Thread-9 - c2d769 session.auth
> active, last_visit=2013-01-17 04:04:07.717197
> 2013-01-17 04:04:42,816 - Thread-4 - c2d769 session.auth
> is None
> 2013-01-17 04:04:48,862 - Thread-10 - c2d769 session.auth
> is None
> 2013-01-17 04:04:49,251 - Thread-6 - c2d769 session.auth
> is None
> 2013-01-17 04:05:35,713 - Thread-7 - c2d769 session.auth
> is None
> 2013-01-17 04:06:39,764 - Thread-8 - c2d769 session.auth
> active, last_visit=2013-01-17 04:06:10.853567
> 2013-01-17 04:06:39,803 - Thread-2 - c2d769 session.auth
> is None
> 2013-01-17 04:07:35,154 - Thread-8 - c2d769 session.auth
> active, last_visit=2013-01-17 04:07:00.261709
> 2013-01-17 04:07:40,860 - Thread-9 - c2d769 session.auth
> is None
> 2013-01-17 04:07:46,176 - Thread-8 - c2d769 session.auth
> is None
> 2013-01-17 04:07:46,266 - Thread-5 - c2d769 session.auth
> is None
> 2013-01-17 04:08:27,416 - Thread-9 - c2d769 session.auth
> active, last_visit=2013-01-17 04:08:03.492030
> 2013-01-17 04:08:27,436 - Thread-2 - c2d769 session.auth
> is None
> 2013-01-17 04:09:31,485 - Thread-10 - c2d769 session.auth
> is None
> 2013-01-17 04:11:21,903 - Thread-7 - c2d769 session.auth
> is None
> 2013-01-17 04:12:20,207 - Thread-10 - c2d769 session.auth
> is None
>
> (the c2d769 is a hash of the cookie, and identifies the client)
>
> As you can see, very often (for this specific client, other clients have
> fewer problems), the session.auth is not there. But then suddenly, in the
> following request, it is there again.
>
> What can be causing this strange problem?
>
> Thanks,
> Daniel
>
>
--
