Bug: Web time out - logged out user - refresh logs in again

[saloynton]

Carlos - I know we've discussed this and there may be tickets for it?
But it's now one of the few big issues for the web.
Logs below...

From Scott:

It was a passing comment of how the scientist was testing with the web client went away to complete some bench work and came back to find the the web client had logged her out.

Working between the bench and computer is something that is common practice so this could be a problematic issue for the web if it logs users out when they are working with it.

[wmoore]

I'll have a look at getBlitzConnection() to see if I can understand and document this a bit better.

[Will Moore <will@…>]

(In [fe0c774673d869a14155baaf905ed8af4bc1cf89/ome.git] on branch develop) Adding debug statements to getBlitzConnection() in webgateway. See #5807

[wmoore]

16-minute delay is enough to log out user, even though I have

$ omero config set omero.sessions.timeout 3600000

Wed, 08 Jun 2011 15:17:47 cache        DEBUG       set: img_None/7701/0x3-c1-212:1285-00FF00-2-319:2753-FF0000-3-279:1534-FFFFFF-mc-q-r-t
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    :: (session) root localhost 4064
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    :: (request) None None None
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    trying stored connection with userAgent: OMERO.web  ckey: S:15b5b0b1-8053-487b-9533-c0edb4cea35b#1
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    [('S:15b5b0b1-8053-487b-9533-c0edb4cea35b#1', <webclient.webclient_gateway.OmeroWebGateway object at 0x22ba850>)]
Wed, 08 Jun 2011 15:33:53 blitz_gateway DEBUG    Traceback (most recent call last):
  File "/Users/will/Desktop/OMERO/dist/lib/python/omero/gateway/__init__.py", line 1278, in keepAlive
    return self.c.sf.keepAlive(self._proxies['admin']._obj)
  File "/Users/will/Desktop/OMERO/dist/lib/python/omero_API_ice.py", line 312, in keepAlive
    return _M_omero.api.ServiceFactory._op_keepAlive.invoke(self, ((proxy, ), _ctx))
ConnectionLostException: Ice.ConnectionLostException:
recv() returned zero

Wed, 08 Jun 2011 15:33:53 blitz_gateway DEBUG    ... lost, reconnecting
Wed, 08 Jun 2011 15:33:53 webgateway   INFO     Failed keepalive for connection S:15b5b0b1-8053-487b-9533-c0edb4cea35b#1
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    :: (session) root localhost 4064
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    :: (request) None None None
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    trying stored connection with userAgent: OMERO.web  ckey: S:15b5b0b1-8053-487b-9533-c0edb4cea35b#1
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    []
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    creating new connection with ckey "S:", sUuid "15b5b0b1-8053-487b-9533-c0edb4cea35b" (False)
Wed, 08 Jun 2011 15:33:53 blitz_gateway DEBUG    Connect attempt, sUuid=15b5b0b1-8053-487b-9533-c0edb4cea35b, group=None, self.sUuid=None
Wed, 08 Jun 2011 15:33:53 blitz_gateway DEBUG    connected? False
Wed, 08 Jun 2011 15:33:53 blitz_gateway DEBUG    Error: exception ::Glacier2::PermissionDeniedException
{
    reason = Password check failed
}
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    created new connection <webclient.webclient_gateway.OmeroWebGateway object at 0x2b87250>
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    connection failed with provided login information, bail out
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    :: (session) root localhost 4064
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    :: (request) None None None
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    trying stored connection with userAgent: OMERO.web  ckey: S:15b5b0b1-8053-487b-9533-c0edb4cea35b#1
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    []
Wed, 08 Jun 2011 15:33:53 webgateway   DEBUG    creating new connection with ckey "S:", sUuid "15b5b0b1-8053-487b-9533-c0edb4cea35b" (False)
Wed, 08 Jun 2011 15:33:53 blitz_gateway DEBUG    Connect attempt, sUuid=15b5b0b1-8053-487b-9533-c0edb4cea35b, group=None, self.sUuid=None
Wed, 08 Jun 2011 15:33:53 blitz_gateway DEBUG    connected? False
Wed, 08 Jun 2011 15:33:57 blitz_gateway DEBUG    Error: exception ::Glacier2::PermissionDeniedException
{
    reason = Password check failed
}
Wed, 08 Jun 2011 15:33:57 webgateway   DEBUG    created new connection <webclient.webclient_gateway.OmeroWebGateway object at 0x2b87970>
Wed, 08 Jun 2011 15:33:57 webgateway   DEBUG    connection failed with provided login information, bail out

[wmoore]

And, following from above, a refresh of the login screen is enough to log me back in.

Wed, 08 Jun 2011 15:41:05 webgateway   DEBUG    :: (session) root localhost 4064
Wed, 08 Jun 2011 15:41:05 webgateway   DEBUG    :: (request) None None None
Wed, 08 Jun 2011 15:41:05 webgateway   DEBUG    trying stored connection with userAgent: OMERO.web  ckey: S:
Wed, 08 Jun 2011 15:41:05 webgateway   DEBUG    []
Wed, 08 Jun 2011 15:41:05 webgateway   DEBUG    creating new connection with ckey "S:", sUuid "None" (False)
Wed, 08 Jun 2011 15:41:05 blitz_gateway DEBUG    Connect attempt, sUuid=None, group=None, self.sUuid=None
Wed, 08 Jun 2011 15:41:05 blitz_gateway DEBUG    Creating Session...
Wed, 08 Jun 2011 15:41:07 blitz_gateway DEBUG    ## Creating proxies
Wed, 08 Jun 2011 15:41:08 blitz_gateway DEBUG    Session created with timeout: 3600000 & timeToLive: 0
Wed, 08 Jun 2011 15:41:08 blitz_gateway DEBUG    ## Reusing proxies
Wed, 08 Jun 2011 15:41:08 blitz_gateway DEBUG    ## - refreshing getAdminService
Wed, 08 Jun 2011 15:41:08 blitz_gateway INFO     created connection (uuid=e7d0aeb4-e167-4f20-b7fc-4b6f00663990)
Wed, 08 Jun 2011 15:41:08 blitz_gateway DEBUG    .. connected!
Wed, 08 Jun 2011 15:41:10 webgateway   DEBUG    created new connection <webclient.webclient_gateway.OmeroWebGateway object at 0x26625d0>
Wed, 08 Jun 2011 15:41:10 webgateway   DEBUG    [('S:e7d0aeb4-e167-4f20-b7fc-4b6f00663990#None', <webclient.webclient_gateway.OmeroWebGateway object at 0x26625d0>)]
Wed, 08 Jun 2011 15:41:10 webgateway   DEBUG    blitz session key: e7d0aeb4-e167-4f20-b7fc-4b6f00663990
Wed, 08 Jun 2011 15:41:10 webgateway   DEBUG    stored as session.S:e7d0aeb4-e167-4f20-b7fc-4b6f00663990#None
Wed, 08 Jun 2011 15:41:10 omero.util.UpgradeCheck DEBUG    Attempting to connect to http://upgrade.openmicroscopy.org.uk/?os.version=Darwin+Kernel+Version+9.8.0%3A+Wed+Jul+15+16%3A55%3A01+PDT+2009%3B+root%3Axnu-1228.15.4%7E1%2FRELEASE_I386&os.arch=i386&version=4.3.0-DEV&python.compiler=GCC+4.0.1+%28Apple+Inc.+build+5465%29&python.build=%28%27r251%3A54863%27%2C+%27Dec+16+2010+14%3A12%3A43%27%29&os.name=Darwin&python.version=2.5.1
Wed, 08 Jun 2011 15:41:12 omero.util.UpgradeCheck INFO     no update needed
Wed, 08 Jun 2011 15:41:12 utils        ERROR    Up to date.

Wed, 08 Jun 2011 15:41:12 webgateway   DEBUG    :: (session) root localhost 4064
Wed, 08 Jun 2011 15:41:12 webgateway   DEBUG    :: (request) None None None
Wed, 08 Jun 2011 15:41:12 webgateway   DEBUG    trying stored connection with userAgent: OMERO.web  ckey: S:e7d0aeb4-e167-4f20-b7fc-4b6f00663990#None
Wed, 08 Jun 2011 15:41:12 webgateway   DEBUG    [('S:e7d0aeb4-e167-4f20-b7fc-4b6f00663990#None', <webclient.webclient_gateway.OmeroWebGateway object at 0x26625d0>)]
Wed, 08 Jun 2011 15:41:12 views-web    DEBUG    TEMPLATE: webclient/data/containers.html
Wed, 08 Jun 2011 15:41:14 webgateway   DEBUG    :: (session) root localhost 4064
Wed, 08 Jun 2011 15:41:14 webgateway   DEBUG    :: (request) None None None
Wed, 08 Jun 2011 15:41:14 webgateway   DEBUG    trying stored connection with userAgent: OMERO.web  ckey: S:e7d0aeb4-e167-4f20-b7fc-4b6f00663990#None
Wed, 08 Jun 2011 15:41:14 webgateway   DEBUG    [('S:e7d0aeb4-e167-4f20-b7fc-4b6f00663990#None', <webclient.webclient_gateway.OmeroWebGateway object at 0x26625d0>)]
Wed, 08 Jun 2011 15:41:14 views-web    DEBUG    TEMPLATE: webclient/data/containers_tree.html
Wed, 08 Jun 2011 15:41:24 webgateway   DEBUG    :: (session) root localhost 4064
Wed, 08 Jun 2011 15:41:24 webgateway   DEBUG    :: (request) None None None
Wed, 08 Jun 2011 15:41:24 webgateway   DEBUG    trying stored connection with userAgent: OMERO.web  ckey: S:e7d0aeb4-e167-4f20-b7fc-4b6f00663990#None
Wed, 08 Jun 2011 15:41:24 webgateway   DEBUG    [('S:e7d0aeb4-e167-4f20-b7fc-4b6f00663990#None', <webclient.webclient_gateway.OmeroWebGateway object at 0x26625d0>)]

[jmoore]

Be sure to compare #5835 and the commit there. Exceptions are still escaping and going all the way up the stack, which certainly led to my being logged out.

[Will Moore <will@…>]

(In [0c5bc4d31e4159e495df70ffb49c729bae30802d/ome.git] on branch develop) Improving debug logging of connect() in Blitz gateway. See #5807

[cneves]

Are all these tests, and in fact the issue, focused on the win2k8 server, or is this a wide spread thing?

After changing windows to force the single thread worker (#5674) I retried this and no longer got logged out after 5 minutes like before. Waiting 20 minutes did log me out, but looking at the Blitz logs shows that the session was reaped due to timeout. No timeout was set on the omero config.

I have since configured the 2k8 system to have a 24 hour timeout and will test one more time before closing shop today.

The other issue with the log in happening with a simple refresh of the login page I have too, and while I didn't debug it yet it should be a simple cleanup issue.

[wmoore]

This was not on the Windows machine - was on my laptop.

I had the timeout set to one hour (printed in the logs as 'Session created with timeout: 3600000 & timeToLive: 0'.

The login is restored with a refresh of the login page, so question is why are we getting sent to login in the first place? (first log above).

If you can fix that issue then I think we should be good!

[cneves]

Apparently the cause for the log out is #5849. The refresh to log in again works because omeroweb keeps the user credentials in the django session, but that is still a bug, as the correct behaviour would be to always remove that information when an exception leads to showing the login page, correctly so in this case as the session was closed externally.

[Carlos Neves <carlos@…>]

(In [017878a9f8af86129b3b49ed53380af85f3c729e/ome.git] on branch develop) Doing proper session cleanup when a failed join is detected, to prevent webclient from doing re-login on refresh (see #5807)

[cneves]

I have tested this as best as I could and it seems that the re login issue is completely resolved. The premature log out is being handled elsewhere (#5849), closing this one.