Task #8812 (closed)
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 7 years ago by wmoore
comment:2 Changed 7 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 7 years ago by atarkowska
- Keywords testing phase1 added
comment:4 Changed 7 years ago by atarkowska
- Cc web-team@… added; atarkowska removed
- Sprint set to 2012-06-05 (16)
comment:5 Changed 7 years ago by saloynton
- Priority changed from minor to blocker
comment:6 Changed 7 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 7 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 7 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 7 years ago by cxallan
- Remaining Time changed from 0.5 to 0
- Status changed from accepted to closed
comment:10 Changed 7 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.
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