Warning: Can't synchronize with repository "(default)" (/home/git/ome.git does not appear to be a Git repository.). Look in the Trac log for more information.
Notice: In order to edit this ticket you need to be either: a Product Owner, The owner or the reporter of the ticket, or, in case of a Task not yet assigned, a team_member"

Task #8812 (closed)

Opened 12 years ago

Closed 12 years ago

Last modified 12 years ago

Bug:Timeout issue

Reported by: saloynton Owned by: cxallan
Priority: blocker Milestone: OMERO-4.4
Component: Web Version: n.a.
Keywords: testing,phase1 Cc: web-team@…, jamoore
Resources: n.a. Referenced By: n.a.
References: n.a. Remaining Time: 0.0d
Sprint: 2012-06-19 (17)

Description

I keep being logged out. Might be a timeout

  • 10.6 Safari
  • Reported by Andrew.
  • OMERO.web 4.3.3-2496-c28cd2a-ice33-b64

Change History (10)

comment:1 Changed 12 years ago by wmoore

This just happend to me too:

Web logs

2012-05-22 10:01:23,397 DEBUG [                           omero.gateway] (proc.84154) connect:1649 Connect attempt, sUuid=f7dc0f68-a85b-4565-b8b9-c36f8420a03a, group=None, self.sUuid=None
2012-05-22 10:01:23,397 DEBUG [                           omero.gateway] (proc.84154) connect:1659 connected? False
2012-05-22 10:01:23,420 DEBUG [                           omero.gateway] (proc.84154) connect:1666 Joined Session OK with Uuid: f7dc0f68-a85b-4565-b8b9-c36f8420a03a and timeToIdle: 600000, timeToLive: 0
2012-05-22 10:01:23,420 DEBUG [                           omero.gateway] (proc.84154) _createProxies:1515 ## Creating proxies
2012-05-22 10:01:23,432  INFO [                           omero.gateway] (proc.84154) connect:1733 created connection (uuid=f7dc0f68-a85b-4565-b8b9-c36f8420a03a)
2012-05-22 10:01:23,432 DEBUG [                           omero.gateway] (proc.84154) connect:1745 .. connected!
2012-05-22 10:01:23,432 DEBUG [                     omeroweb.decorators] (proc.84154) get_authenticated_connection:258 Connector valid, session successfully joined.
2012-05-22 10:01:23,432 DEBUG [                     omeroweb.decorators] (proc.84154) get_connection:159 Is valid public URL? True
2012-05-22 10:01:23,432 DEBUG [                     omeroweb.decorators] (proc.84154) get_connection:179 Is anonymous? False
2012-05-22 10:01:23,461 DEBUG [                     omeroweb.decorators] (proc.84154) wrapper:354 Rendering template: webclient/annotations/metadata_general.html
2012-05-22 10:01:23,498 DEBUG [                     omeroweb.decorators] (proc.84154) wrapped:314 Doing connection cleanup? True
2012-05-22 10:01:28,616 DEBUG [                     omeroweb.decorators] (proc.84154) wrapped:287 Connection not provided, attempting to get one.
2012-05-22 10:01:28,616 DEBUG [                     omeroweb.decorators] (proc.84154) get_authenticated_connection:194 Is SSL? False
2012-05-22 10:01:28,616 DEBUG [                     omeroweb.decorators] (proc.84154) get_authenticated_connection:252 Django session connector: <omeroweb.connector.Connector object at 0x105c71650>
2012-05-22 10:01:28,616 DEBUG [                           omero.gateway] (proc.84154) _resetOmeroClient:1618 localhost
2012-05-22 10:01:28,616 DEBUG [                           omero.gateway] (proc.84154) _resetOmeroClient:1619 4064
2012-05-22 10:01:28,616 DEBUG [                           omero.gateway] (proc.84154) _resetOmeroClient:1620 []
2012-05-22 10:01:28,619 DEBUG [                           omero.gateway] (proc.84154) connect:1649 Connect attempt, sUuid=f7dc0f68-a85b-4565-b8b9-c36f8420a03a, group=None, self.sUuid=None
2012-05-22 10:01:28,619 DEBUG [                           omero.gateway] (proc.84154) connect:1659 connected? False
2012-05-22 10:01:28,644 DEBUG [                           omero.gateway] (proc.84154) connect:1671 Error: exception ::Glacier2::PermissionDeniedException
{
    reason = Password check failed for 'f7dc0f68-a85b-4565-b8b9-c36f8420a03a': [user=will, created=2012-05-22 09:49:01.197, closed=2012-05-22 10:01:28.262259]
}
2012-05-22 10:01:28,644 DEBUG [                     omeroweb.decorators] (proc.84154) get_authenticated_connection:263 Connector is no longer valid, destroying...
2012-05-22 10:01:28,644 DEBUG [                     omeroweb.decorators] (proc.84154) get_connection:159 Is valid public URL? True
2012-05-22 10:01:28,645 DEBUG [                     omeroweb.decorators] (proc.84154) on_not_logged_in:108 Request is Ajax, returning HTTP 403.
2012-05-22 10:01:28,897 DEBUG [                     omeroweb.decorators] (proc.84154) wrapped:287 Connection not provided, attempting to get one.
2012-05-22 10:01:28,897 DEBUG [                     omeroweb.decorators] (proc.84154) get_authenticated_connection:194 Is SSL? False
2012-05-22 10:01:28,897 DEBUG [                     omeroweb.decorators] (proc.84154) get_authenticated_connection:207 No Server ID available.
2012-05-22 10:01:28,898 DEBUG [                     omeroweb.decorators] (proc.84154) get_connection:159 Is valid public URL? True
2012-05-22 10:01:28,898 DEBUG [                     omeroweb.decorators] (proc.84154) on_not_logged_in:111 Request is not Ajax, redirecting to /webclient/login/

Blitz log

2012-05-22 10:01:23,447 INFO  [    ome.security.basic.BasicEventContext] (l.Server-5)  cctx:    group=5
2012-05-22 10:01:23,447 INFO  [         ome.security.basic.EventHandler] (l.Server-5)  Auth:    user=3,group=5,event=null(User),sess=f7dc0f68-a85b-4565-b8b9-c36f8420a03a
2012-05-22 10:01:23,452 INFO  [                 org.perf4j.TimingLogger] (l.Server-5) start[1337677283445] time[7] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2012-05-22 10:01:23,452 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Rslt:    ome.model.screen.Plate:Id_2
2012-05-22 10:01:23,455 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Meth:    interface ome.api.IQuery.findAllByQuery
2012-05-22 10:01:23,455 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Args:    [select l from PlateAnnotationLink as l join fetch l.details.owner join fetch l.details.creationEvent join fetch l.child as a join fetch
 a.details.owner join fetch a.details.creationEvent where l.parent.id=2, null]
2012-05-22 10:01:23,457 INFO  [    ome.security.basic.BasicEventContext] (l.Server-9)  cctx:    group=5
2012-05-22 10:01:23,457 INFO  [         ome.security.basic.EventHandler] (l.Server-9)  Auth:    user=3,group=5,event=null(User),sess=f7dc0f68-a85b-4565-b8b9-c36f8420a03a
2012-05-22 10:01:23,460 INFO  [                 org.perf4j.TimingLogger] (l.Server-9) start[1337677283455] time[5] tag[omero.call.success.ome.logic.QueryImpl.findAllByQuery]
2012-05-22 10:01:23,460 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Rslt:    ()
2012-05-22 10:01:23,499 INFO  [e.services.sessions.SessionContext$Count] (l.Server-4) -Reference count: f7dc0f68-a85b-4565-b8b9-c36f8420a03a=1
2012-05-22 10:01:28,237 INFO  [e.services.sessions.SessionContext$Count] (l.Server-1) -Reference count: f7dc0f68-a85b-4565-b8b9-c36f8420a03a=0
2012-05-22 10:01:28,237 INFO  [                      omero.cmd.SessionI] (l.Server-1) doDestroy(ServiceFactoryI(session-c8d967e3-bb6b-43bf-ad90-2cbbdc4ca624/f7dc0f68-a85b-4565-b8b9-c36f8420a03a))2012-05-22 10:01:28,237 INFO  [                      omero.cmd.SessionI] (l.Server-3) Session already removed. Cleaning up blitz state.
2012-05-22 10:01:28,237 INFO  [                      omero.cmd.SessionI] (l.Server-3) doDestroy(ServiceFactoryI(session-738457db-e762-4c5a-8dcc-c6a9e8a95153/75f41251-058a-4958-8e3a-b33c8de2e425))
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Unregistered servant:f7dc0f68-a85b-4565-b8b9-c36f8420a03a/c8d967e3-bb6b-43bf-ad90-2cbbdc4ca624omero.api.IAdmin(omero.api._IAdminTie@f15fbd89)
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Removed servant from adapter: c8d967e3-bb6b-43bf-ad90-2cbbdc4ca624omero.api.IAdmin
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-3) Unregistered servant:75f41251-058a-4958-8e3a-b33c8de2e425/738457db-e762-4c5a-8dcc-c6a9e8a95153omero.api.ISession(omero.api._ISessionTie@bfe69215)
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-3) Removed servant from adapter: 738457db-e762-4c5a-8dcc-c6a9e8a95153omero.api.ISession
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-3) Unregistered servant:75f41251-058a-4958-8e3a-b33c8de2e425/738457db-e762-4c5a-8dcc-c6a9e8a95153omero.api.IConfig(omero.api._IConfigTie@aac29655)2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-3) Removed servant from adapter: 738457db-e762-4c5a-8dcc-c6a9e8a95153omero.api.IConfig
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Unregistered servant:f7dc0f68-a85b-4565-b8b9-c36f8420a03a/4071dba5-8c52-4013-b977-c7a6cbc2570fomero.api.IContainer(omero.api._IContainerTie@c9a2e3
bb)
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Removed servant from adapter: 4071dba5-8c52-4013-b977-c7a6cbc2570fomero.api.IContainer
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-3) Unregistered servant:75f41251-058a-4958-8e3a-b33c8de2e425/738457db-e762-4c5a-8dcc-c6a9e8a95153omero.api.IAdmin(omero.api._IAdminTie@c16815f)
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-3) Removed servant from adapter: 738457db-e762-4c5a-8dcc-c6a9e8a95153omero.api.IAdmin
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Unregistered servant:f7dc0f68-a85b-4565-b8b9-c36f8420a03a/ebbff6ed-b154-4696-8320-f34a9b99f44aomero.api.IContainer(omero.api._IContainerTie@c564e0
db)
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Removed servant from adapter: ebbff6ed-b154-4696-8320-f34a9b99f44aomero.api.IContainer
2012-05-22 10:01:28,238 INFO  [ome.services.sessions.SessionManagerImpl] (l.Server-3) closeSession called but doesn't exist: 75f41251-058a-4958-8e3a-b33c8de2e425
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Unregistered servant:f7dc0f68-a85b-4565-b8b9-c36f8420a03a/f2adeeb3-9949-48b5-b607-f4a7aa68d1e8omero.api.ISession(omero.api._ISessionTie@b68c9172)
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Removed servant from adapter: f2adeeb3-9949-48b5-b607-f4a7aa68d1e8omero.api.ISession
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Unregistered servant:f7dc0f68-a85b-4565-b8b9-c36f8420a03a/272959e8-e117-4065-8476-931733a01bc7omero.api.IAdmin(omero.api._IAdminTie@ac82baf8)
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Removed servant from adapter: 272959e8-e117-4065-8476-931733a01bc7omero.api.IAdmin
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Unregistered servant:f7dc0f68-a85b-4565-b8b9-c36f8420a03a/997846a0-baec-40dd-8eec-a55403dda7f3omero.api.ISession(omero.api._ISessionTie@99f60754)
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Removed servant from adapter: 997846a0-baec-40dd-8eec-a55403dda7f3omero.api.ISession
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Unregistered servant:f7dc0f68-a85b-4565-b8b9-c36f8420a03a/ebc83b2e-c3ae-4d73-98f6-406b7e6d5835omero.api.ISession(omero.api._ISessionTie@cfde004)
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Removed servant from adapter: ebc83b2e-c3ae-4d73-98f6-406b7e6d5835omero.api.ISession
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Unregistered servant:f7dc0f68-a85b-4565-b8b9-c36f8420a03a/6bff5323-a0d7-4182-9ad5-2158ff66c82aomero.api.ISession(omero.api._ISessionTie@f21ef470)
2012-05-22 10:01:28,238 INFO  [                      omero.cmd.SessionI] (l.Server-1) Removed servant from adapter: 6bff5323-a0d7-4182-9ad5-2158ff66c82aomero.api.ISession

...
hundreds (~400) more lines like these

comment:2 Changed 12 years ago by wmoore

  • Cc atarkowska jmoore added; web-team@… removed
  • Owner changed from web-team@… to cxallan

Chris - Not sure if there's enough info here to work out what's going on?

I'll add more info if I can. Any more logging we can do to help?

comment:3 Changed 12 years ago by atarkowska

  • Keywords testing phase1 added

comment:4 Changed 12 years ago by atarkowska

  • Cc web-team@… added; atarkowska removed
  • Sprint set to 2012-06-05 (16)

comment:5 Changed 12 years ago by saloynton

  • Priority changed from minor to blocker

comment:6 Changed 12 years ago by jburel

  • Sprint changed from 2012-06-05 (16) to 2012-06-19 (17)

Moved from sprint 2012-06-05 (16)

comment:7 Changed 12 years ago by cxallan

  • Remaining Time set to 0.5
  • Status changed from new to accepted

Logging additions along with bringing decorator and connector logging to the DEBUG level by default are now on the sprint17-bugfixes branch ready for testing:

comment:8 Changed 12 years ago by cxallan

After logging has been enabled and with some reasonably careful testing we can now reproduce:

134.36.64.137 - - [12/Jun/2012:13:58:02 -0400] "GET / HTTP/1.1" 302 332
134.36.64.137 - - [12/Jun/2012:13:58:02 -0400] "GET /omero/webclient/ HTTP/1.1" 302 -
134.36.64.137 - - [12/Jun/2012:13:58:02 -0400] "GET /omero/webclient/login/?url=%2Fomero%2Fwebclient%2F HTTP/1.1" 200 3377
134.36.64.137 - - [12/Jun/2012:13:58:07 -0400] "POST /omero/webclient/login/?url=%2Fomero%2Fwebclient%2F HTTP/1.1" 302 -
134.36.64.137 - - [12/Jun/2012:13:58:09 -0400] "GET /omero/webclient/ HTTP/1.1" 200 110695
134.36.64.137 - - [12/Jun/2012:13:58:10 -0400] "GET /omero/webadmin/myphoto/ HTTP/1.1" 200 23556
134.36.64.137 - - [12/Jun/2012:13:58:10 -0400] "GET /omero/webclient/activities/ HTTP/1.1" 200 529
134.36.64.137 - - [12/Jun/2012:13:58:10 -0400] "GET /omero/webclient/load_data/?view=tree HTTP/1.1" 200 1020
134.36.64.137 - - [12/Jun/2012:13:59:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:00:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:01:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:02:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:03:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:04:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:05:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:06:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:07:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:08:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:09:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:10:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 2
134.36.64.137 - - [12/Jun/2012:14:11:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 17
134.36.64.137 - - [12/Jun/2012:14:12:10 -0400] "GET /omero/webclient/keepalive_ping/ HTTP/1.1" 200 17

Basically sessions only last for 10 minutes. The 17 byte keepalive_ping responses are "Connection Failed" as soon as the timeouts are hit.

Relevant lines of Blitz-0.log:

...
2012-06-12 13:58:07,726 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-32) Created session ServiceFactoryI(session-cd8c6abb-100d-4b50-a227-50041b56b80c/bed38551-5ce1-48f1-a4ab-7aa54fccb8a9) for user bob (agent=OMERO.web)
2012-06-12 13:58:07,729 INFO  [                      omero.cmd.SessionI] (.Server-33) Added servant to adapter: bed38551-5ce1-48f1-a4ab-7aa54fccb8a9/cd8c6abb-100d-4b50-a227-50041b56b80comero.api.ISession(omero.api._ISessionTie@5d7eea6b)
...
2012-06-12 14:10:10,413 INFO  [e.services.sessions.SessionContext$Count] (.Server-32) -Reference count: bed38551-5ce1-48f1-a4ab-7aa54fccb8a9=1
2012-06-12 14:10:15,188 INFO  [e.services.sessions.SessionContext$Count] (.Server-33) -Reference count: bed38551-5ce1-48f1-a4ab-7aa54fccb8a9=0
2012-06-12 14:10:15,188 INFO  [                      omero.cmd.SessionI] (.Server-33) doDestroy(ServiceFactoryI(session-7ef83e14-c294-4001-a80d-1e4398d5c25c/bed38551-5ce1-48f1-a4ab-7aa54fccb8a9))
...

comment:9 Changed 12 years ago by cxallan

  • Remaining Time changed from 0.5 to 0
  • Status changed from accepted to closed

comment:10 Changed 12 years ago by Chris Allan <callan@…>

(In [832a8b76f4fb9ad5e4f623d60d928011453adf29/ome.git] on branch develop) Revert "Increase decorator and connector logging to DEBUG. (See #8812)"

This reverts commit 4ba89319102c085bea1b4316f9cffbf84d29f3f8.

Conflicts:

components/tools/OmeroPy/scripts

Note: See TracTickets for help on using tickets. You may also have a look at Agilo extensions to the ticket.

1.3.13-PRO © 2008-2011 Agilo Software all rights reserved (this page was served in: 0.66631 sec.)

We're Hiring!