OMEROweb Internal Server Error

[chriswood]

Hi,

Sometimes when logging into the OMERO.web client (like after the weekend, or a user that hasn't logged on before), after entering my username and password, the page will wait for a while and then give an Internal Server Error. I can click back on the browser, re-enter username/password, and then everything works fine.

I am on CentOs 6, OMERO 4.4.5, apache httpd, fastcgi-tcp

The Apache httpd error log gives:

Code: Select all

[Tue Nov 27 13:47:47 2012] [error] [client 10.2.20.135] FastCGI: comm with server "/home/omerouser/OMERO.server/var/omero.fcgi" aborted: idle timeout (30 sec), referer: http://omero/omero/webclient/login/?url=%2Fomero%2Fwebclient%2F
[Tue Nov 27 13:47:47 2012] [error] [client 10.2.20.135] FastCGI: incomplete headers (0 bytes) received from server "/home/omerouser/OMERO.server/var/omero.fcgi", referer: http://omero/omero/webclient/login/?url=%2Fomero%2Fwebclient%2F


Here is the OMEROweb.log from the same timeframe:

Code: Select all

2012-11-27 19:46:03,287 DEBUG [                     omeroweb.decorators] (proc.21545) wrapped:380 Doing connection cleanup? True
2012-11-27 19:47:59,001 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1625 localhost
2012-11-27 19:47:59,001 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1626 4064
2012-11-27 19:47:59,001 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1627 []
2012-11-27 19:47:59,005 DEBUG [                           omero.gateway] (proc.21545) connect:1656 Connect attempt, sUuid=None, group=None, self.sUuid=None
2012-11-27 19:47:59,005 DEBUG [                           omero.gateway] (proc.21545) connect:1704 Creating Session...
2012-11-27 19:47:59,100 DEBUG [                           omero.gateway] (proc.21545) _createProxies:1525 ## Creating proxies
2012-11-27 19:47:59,101 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.session.uuid' to '16c495b9-1532-490f-92de-aa961efcc871'
2012-11-27 19:47:59,101 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.client.uuid' to 'c42c6295-77b2-4682-a3c4-e7bb85978a17'
2012-11-27 19:47:59,101 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroGroup:115 Key 'omero.group' not found in <ServiceOptsDict: {'omero.session.uuid': '16c495b9-1532-490f-92de-aa961efcc871', 'omero.client.uuid': 'c42c6295-77b2-4682-a3c4-e7bb85978a17'}>
2012-11-27 19:47:59,102 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroUser:127 Key 'omero.user' not found in <ServiceOptsDict: {'omero.session.uuid': '16c495b9-1532-490f-92de-aa961efcc871', 'omero.client.uuid': 'c42c6295-77b2-4682-a3c4-e7bb85978a17'}>
2012-11-27 19:47:59,102 DEBUG [                           omero.gateway] (proc.21545) connect:1706 Session created
2012-11-27 19:47:59,102 DEBUG [                           omero.gateway] (proc.21545) _createProxies:1521 ## Reusing proxies
2012-11-27 19:47:59,103  INFO [                           omero.gateway] (proc.21545) connect:1742 created connection (uuid=16c495b9-1532-490f-92de-aa961efcc871)
2012-11-27 19:47:59,103 DEBUG [                           omero.gateway] (proc.21545) connect:1754 .. connected!
2012-11-27 19:47:59,119 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1625 localhost
2012-11-27 19:47:59,120 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1626 4064
2012-11-27 19:47:59,120 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1627 []
2012-11-27 19:47:59,123 DEBUG [                           omero.gateway] (proc.21545) connect:1656 Connect attempt, sUuid=None, group=None, self.sUuid=None
2012-11-27 19:47:59,123 DEBUG [                           omero.gateway] (proc.21545) connect:1704 Creating Session...
2012-11-27 19:47:59,213 DEBUG [                           omero.gateway] (proc.21545) _createProxies:1525 ## Creating proxies
2012-11-27 19:47:59,215 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.session.uuid' to 'db697a64-7b68-4ef6-a442-b8c56fafe7b8'
2012-11-27 19:47:59,215 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.client.uuid' to 'b8d81a9b-a7e0-48e4-a655-f84dc108f1da'
2012-11-27 19:47:59,215 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroGroup:115 Key 'omero.group' not found in <ServiceOptsDict: {'omero.session.uuid': 'db697a64-7b68-4ef6-a442-b8c56fafe7b8', 'omero.client.uuid': 'b8d81a9b-a7e0-48e4-a655-f84dc108f1da'}>
2012-11-27 19:47:59,216 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroUser:127 Key 'omero.user' not found in <ServiceOptsDict: {'omero.session.uuid': 'db697a64-7b68-4ef6-a442-b8c56fafe7b8', 'omero.client.uuid': 'b8d81a9b-a7e0-48e4-a655-f84dc108f1da'}>
2012-11-27 19:47:59,216 DEBUG [                           omero.gateway] (proc.21545) connect:1706 Session created
2012-11-27 19:47:59,216 DEBUG [                           omero.gateway] (proc.21545) _createProxies:1521 ## Reusing proxies
2012-11-27 19:47:59,217  INFO [                           omero.gateway] (proc.21545) connect:1742 created connection (uuid=db697a64-7b68-4ef6-a442-b8c56fafe7b8)
2012-11-27 19:47:59,217 DEBUG [                           omero.gateway] (proc.21545) connect:1754 .. connected!
2012-11-27 19:47:59,245 DEBUG [                 omero.util.UpgradeCheck] (proc.21545) run:118 Attempting to connect to http://upgrade.openmicroscopy.org.uk/?os.version=%231+SMP+Tue+Sep+25+21%3A43%3A11+UTC+2012&os.arch=x86_64&version=4.4.5-ice34-b20&python.compiler=GCC+4.4.6+20120305+%28Red+Hat+4.4.6-4%29&python.build=%28%27r266%3A84292%27%2C+%27Sep+11+2012+08%3A34%3A23%27%29&os.name=Linux&python.version=2.6.6
2012-11-27 19:48:00,217  INFO [                 omero.util.UpgradeCheck] (proc.21545) run:130 no update needed
2012-11-27 19:48:00,217 DEBUG [        omeroweb.webadmin.webadmin_utils] (proc.21545) upgradeCheck:29 Up to date.

2012-11-27 19:48:01,412 DEBUG [                     omeroweb.decorators] (proc.21545) wrapped:351 Connection not provided, attempting to get one.
2012-11-27 19:48:01,412 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:250 Is SSL? False
2012-11-27 19:48:01,413 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:252 Connector: <omeroweb.connector.Connector object at 0x446d7d0>
2012-11-27 19:48:01,413 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:313 Django session connector: <omeroweb.connector.Connector object at 0x446d7d0>
2012-11-27 19:48:01,413 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1625 localhost
2012-11-27 19:48:01,414 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1626 4064
2012-11-27 19:48:01,414 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1627 []
2012-11-27 19:48:01,418 DEBUG [                           omero.gateway] (proc.21545) connect:1656 Connect attempt, sUuid=db697a64-7b68-4ef6-a442-b8c56fafe7b8, group=None, self.sUuid=None
2012-11-27 19:48:01,418 DEBUG [                           omero.gateway] (proc.21545) connect:1666 connected? False
2012-11-27 19:48:01,443 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.session.uuid' to 'db697a64-7b68-4ef6-a442-b8c56fafe7b8'
2012-11-27 19:48:01,444 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.client.uuid' to 'a6ed8a7a-3797-4626-8000-1c1edd64930f'
2012-11-27 19:48:01,444 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroGroup:115 Key 'omero.group' not found in <ServiceOptsDict: {'omero.session.uuid': 'db697a64-7b68-4ef6-a442-b8c56fafe7b8', 'omero.client.uuid': 'a6ed8a7a-3797-4626-8000-1c1edd64930f'}>
2012-11-27 19:48:01,444 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroUser:127 Key 'omero.user' not found in <ServiceOptsDict: {'omero.session.uuid': 'db697a64-7b68-4ef6-a442-b8c56fafe7b8', 'omero.client.uuid': 'a6ed8a7a-3797-4626-8000-1c1edd64930f'}>
2012-11-27 19:48:01,444 DEBUG [                           omero.gateway] (proc.21545) connect:1674 Joined Session OK with Uuid: db697a64-7b68-4ef6-a442-b8c56fafe7b8
2012-11-27 19:48:01,445 DEBUG [                           omero.gateway] (proc.21545) _createProxies:1525 ## Creating proxies
2012-11-27 19:48:01,445  INFO [                           omero.gateway] (proc.21545) connect:1742 created connection (uuid=db697a64-7b68-4ef6-a442-b8c56fafe7b8)
2012-11-27 19:48:01,445 DEBUG [                           omero.gateway] (proc.21545) connect:1754 .. connected!
2012-11-27 19:48:01,446 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:319 Connector valid, session successfully joined.
2012-11-27 19:48:01,446 DEBUG [                     omeroweb.decorators] (proc.21545) get_connection:198 Is valid public URL? False
2012-11-27 19:48:01,446 DEBUG [                     omeroweb.decorators] (proc.21545) get_connection:235 Is anonymous? False
2012-11-27 19:48:01,446 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.group' to '-1'
2012-11-27 19:48:01,447 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroShare:139 Key 'omero.share' not found in <ServiceOptsDict: {'omero.session.uuid': 'db697a64-7b68-4ef6-a442-b8c56fafe7b8', 'omero.group': '-1', 'omero.client.uuid': 'a6ed8a7a-3797-4626-8000-1c1edd64930f'}>
2012-11-27 19:48:01,447 DEBUG [                     omeroweb.decorators] (proc.21545) wrapper:423 Rendering template: webclient/activities/activitiesContent.html
2012-11-27 19:48:01,466 DEBUG [                     omeroweb.decorators] (proc.21545) wrapped:380 Doing connection cleanup? True
2012-11-27 19:48:15,893 DEBUG [                     omeroweb.decorators] (proc.21545) wrapped:351 Connection not provided, attempting to get one.
2012-11-27 19:48:15,893 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:250 Is SSL? False
2012-11-27 19:48:15,894 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:252 Connector: <omeroweb.connector.Connector object at 0x38f0550>
2012-11-27 19:48:15,894 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:313 Django session connector: <omeroweb.connector.Connector object at 0x38f0550>
2012-11-27 19:48:15,894 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1625 localhost
2012-11-27 19:48:15,895 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1626 4064
2012-11-27 19:48:15,895 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1627 []
2012-11-27 19:48:15,899 DEBUG [                           omero.gateway] (proc.21545) connect:1656 Connect attempt, sUuid=db697a64-7b68-4ef6-a442-b8c56fafe7b8, group=None, self.sUuid=None
2012-11-27 19:48:15,899 DEBUG [                           omero.gateway] (proc.21545) connect:1666 connected? False
2012-11-27 19:48:15,921 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.session.uuid' to 'db697a64-7b68-4ef6-a442-b8c56fafe7b8'
2012-11-27 19:48:15,921 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.client.uuid' to 'b66740a4-9889-4872-85a4-dc0991246783'
2012-11-27 19:48:15,921 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroGroup:115 Key 'omero.group' not found in <ServiceOptsDict: {'omero.session.uuid': 'db697a64-7b68-4ef6-a442-b8c56fafe7b8', 'omero.client.uuid': 'b66740a4-9889-4872-85a4-dc0991246783'}>
2012-11-27 19:48:15,921 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroUser:127 Key 'omero.user' not found in <ServiceOptsDict: {'omero.session.uuid': 'db697a64-7b68-4ef6-a442-b8c56fafe7b8', 'omero.client.uuid': 'b66740a4-9889-4872-85a4-dc0991246783'}>
2012-11-27 19:48:15,922 DEBUG [                           omero.gateway] (proc.21545) connect:1674 Joined Session OK with Uuid: db697a64-7b68-4ef6-a442-b8c56fafe7b8
2012-11-27 19:48:15,922 DEBUG [                           omero.gateway] (proc.21545) _createProxies:1525 ## Creating proxies
2012-11-27 19:48:15,922  INFO [                           omero.gateway] (proc.21545) connect:1742 created connection (uuid=db697a64-7b68-4ef6-a442-b8c56fafe7b8)
2012-11-27 19:48:15,923 DEBUG [                           omero.gateway] (proc.21545) connect:1754 .. connected!
2012-11-27 19:48:15,923 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:319 Connector valid, session successfully joined.
2012-11-27 19:48:15,923 DEBUG [                     omeroweb.decorators] (proc.21545) get_connection:198 Is valid public URL? False
2012-11-27 19:48:15,923 DEBUG [                     omeroweb.decorators] (proc.21545) get_connection:235 Is anonymous? False
2012-11-27 19:48:15,923 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.group' to '-1'
2012-11-27 19:48:15,924 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroShare:139 Key 'omero.share' not found in <ServiceOptsDict: {'omero.session.uuid': 'db697a64-7b68-4ef6-a442-b8c56fafe7b8', 'omero.group': '-1', 'omero.client.uuid': 'b66740a4-9889-4872-85a4-dc0991246783'}>
2012-11-27 19:48:16,074 DEBUG [                     omeroweb.decorators] (proc.21545) wrapper:423 Rendering template: webclient/data/container_tags.html
2012-11-27 19:48:16,137 DEBUG [                     omeroweb.decorators] (proc.21545) wrapped:380 Doing connection cleanup? True
2012-11-27 19:48:16,826 DEBUG [                     omeroweb.decorators] (proc.21545) wrapped:351 Connection not provided, attempting to get one.
2012-11-27 19:48:16,826 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:250 Is SSL? False
2012-11-27 19:48:16,826 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:252 Connector: <omeroweb.connector.Connector object at 0x3621790>
2012-11-27 19:48:16,827 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:313 Django session connector: <omeroweb.connector.Connector object at 0x3621790>
2012-11-27 19:48:16,827 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1625 localhost
2012-11-27 19:48:16,827 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1626 4064
2012-11-27 19:48:16,827 DEBUG [                           omero.gateway] (proc.21545) _resetOmeroClient:1627 []
2012-11-27 19:48:16,831 DEBUG [                           omero.gateway] (proc.21545) connect:1656 Connect attempt, sUuid=db697a64-7b68-4ef6-a442-b8c56fafe7b8, group=None, self.sUuid=None
2012-11-27 19:48:16,831 DEBUG [                           omero.gateway] (proc.21545) connect:1666 connected? False
2012-11-27 19:48:16,852 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.session.uuid' to 'db697a64-7b68-4ef6-a442-b8c56fafe7b8'
2012-11-27 19:48:16,853 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.client.uuid' to '0d16541b-f30b-4d12-803f-7579f9df7775'
2012-11-27 19:48:16,853 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroGroup:115 Key 'omero.group' not found in <ServiceOptsDict: {'omero.session.uuid': 'db697a64-7b68-4ef6-a442-b8c56fafe7b8', 'omero.client.uuid': '0d16541b-f30b-4d12-803f-7579f9df7775'}>
2012-11-27 19:48:16,853 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroUser:127 Key 'omero.user' not found in <ServiceOptsDict: {'omero.session.uuid': 'db697a64-7b68-4ef6-a442-b8c56fafe7b8', 'omero.client.uuid': '0d16541b-f30b-4d12-803f-7579f9df7775'}>
2012-11-27 19:48:16,853 DEBUG [                           omero.gateway] (proc.21545) connect:1674 Joined Session OK with Uuid: db697a64-7b68-4ef6-a442-b8c56fafe7b8
2012-11-27 19:48:16,853 DEBUG [                           omero.gateway] (proc.21545) _createProxies:1525 ## Creating proxies
2012-11-27 19:48:16,854  INFO [                           omero.gateway] (proc.21545) connect:1742 created connection (uuid=db697a64-7b68-4ef6-a442-b8c56fafe7b8)
2012-11-27 19:48:16,854 DEBUG [                           omero.gateway] (proc.21545) connect:1754 .. connected!
2012-11-27 19:48:16,854 DEBUG [                     omeroweb.decorators] (proc.21545) get_authenticated_connection:319 Connector valid, session successfully joined.
2012-11-27 19:48:16,854 DEBUG [                     omeroweb.decorators] (proc.21545) get_connection:198 Is valid public URL? False
2012-11-27 19:48:16,854 DEBUG [                     omeroweb.decorators] (proc.21545) get_connection:235 Is anonymous? False
2012-11-27 19:48:16,855 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.group' to '-1'
2012-11-27 19:48:16,869 DEBUG [                     omero.gateway.utils] (proc.21545) __setitem__:70 Setting 'omero.group' to 4L
2012-11-27 19:48:16,869 DEBUG [                     omero.gateway.utils] (proc.21545) setOmeroShare:139 Key 'omero.share' not found in <ServiceOptsDict: {'omero.session.uuid': 'db697a64-7b68-4ef6-a442-b8c56fafe7b8', 'omero.group': '4', 'omero.client.uuid': '0d16541b-f30b-4d12-803f-7579f9df7775'}>



Any ideas?

Thanks
Chris

[cxallan]

If you look in your Blitz-0.log for around the same time frame do you have timeouts there connecting to your LDAP server or JDBC errors?

[chriswood]

I didn't see any timeouts, warnings or errors of any kind in the Blitz log. Here it is:

Code: Select all

2012-11-27 13:47:17,644 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.executeCheckPasswordRO(guest)
2012-11-27 13:47:17,644 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Args:   [null, InternalSF@479481162]
2012-11-27 13:47:17,645 INFO  [         ome.security.basic.EventHandler] (Server-100)  Auth:   user=0,group=0,event=null(Sessions),sess=e0937ca4-02ba-47b0-acc8-79e345e8fed1
2012-11-27 13:47:17,648 INFO  [                 org.perf4j.TimingLogger] (Server-100) start[1354045637644] time[4] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$8.doWork]
2012-11-27 13:47:17,648 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Rslt:   true
2012-11-27 13:47:17,649 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2012-11-27 13:47:17,649 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Args:   [null, InternalSF@479481162]
2012-11-27 13:47:17,660 INFO  [         ome.security.basic.EventHandler] (.Server-99)  Auth:   user=0,group=0,event=1214323(Sessions),sess=e0937ca4-02ba-47b0-acc8-79e345e8fed1
2012-11-27 13:47:17,671 INFO  [       ome.security.basic.CurrentDetails] (.Server-99) Adding log:INSERT,class ome.model.meta.Session,223565
2012-11-27 13:47:17,681 INFO  [                 org.perf4j.TimingLogger] (.Server-99) start[1354045637649] time[32] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2012-11-27 13:47:17,681 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Rslt:   (ome.model.meta.Experimenter:Id_1, ome.model.meta.ExperimenterGroup:Id_4, (4, 2), ... 4 more)
2012-11-27 13:47:17,682 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-99) Created session ServiceFactoryI(session-f9ffdadb-f072-4dad-a404-8335c5960de3/0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f) for user guest (agent=OMERO.web)
2012-11-27 13:47:17,690 INFO  [                      omero.cmd.SessionI] (.Server-96) Added servant to adapter: 0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f/f9ffdadb-f072-4dad-a404-8335c5960de3omero.api.ISession(omero.api._ISessionTie@2756814a)
2012-11-27 13:47:17,692 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Meth:   interface ome.api.ISession.getSession
2012-11-27 13:47:17,692 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Args:   [0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f]
2012-11-27 13:47:17,692 INFO  [                 org.perf4j.TimingLogger] (Server-100) start[1354045637692] time[0] tag[omero.call.success.ome.services.sessions.SessionBean.getSession]
2012-11-27 13:47:17,692 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Rslt:   ome.model.meta.Session:Id_223565
2012-11-27 13:47:17,699 INFO  [                      omero.cmd.SessionI] (.Server-99) Added servant to adapter: 0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f/f9ffdadb-f072-4dad-a404-8335c5960de3omero.api.IConfig(omero.api._IConfigTie@3b97eb68)
2012-11-27 13:47:17,701 INFO  [        ome.services.util.ServiceHandler] (.Server-87)  Meth:   interface ome.api.IConfig.getConfigValue
2012-11-27 13:47:17,701 INFO  [        ome.services.util.ServiceHandler] (.Server-87)  Args:   [omero.router.insecure]
2012-11-27 13:47:17,712 INFO  [         ome.security.basic.EventHandler] (.Server-87)  Auth:   user=1,group=4,event=1214324(User),sess=0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f
2012-11-27 13:47:17,715 INFO  [                 org.perf4j.TimingLogger] (.Server-87) start[1354045637701] time[14] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2012-11-27 13:47:17,715 INFO  [        ome.services.util.ServiceHandler] (.Server-87)  Rslt:   OMERO.Glacier2/router:tcp -p 4063 -h @omero.host@
2012-11-27 13:47:17,721 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-96) Found session locally: 0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f
2012-11-27 13:47:17,722 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-96) Rejoining session ServiceFactoryI(session-650ca3f8-cb88-4930-abef-64964bdff995/0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f) (agent=OMERO.web;secure=False)
2012-11-27 13:47:17,726 INFO  [e.services.sessions.SessionContext$Count] (.Server-99) -Reference count: 0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f=1
2012-11-27 13:47:17,726 INFO  [                      omero.cmd.SessionI] (.Server-99) cleanupSelf(ServiceFactoryI(session-f9ffdadb-f072-4dad-a404-8335c5960de3/0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f)).
2012-11-27 13:47:17,726 INFO  [                      omero.cmd.SessionI] (.Server-99) Unregistered servant:0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f/f9ffdadb-f072-4dad-a404-8335c5960de3omero.api.IConfig(omero.api._IConfigTie@3b97eb68)
2012-11-27 13:47:17,726 INFO  [                      omero.cmd.SessionI] (.Server-99) Removed servant from adapter: f9ffdadb-f072-4dad-a404-8335c5960de3omero.api.IConfig
2012-11-27 13:47:17,726 INFO  [                      omero.cmd.SessionI] (.Server-99) Unregistered servant:0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f/f9ffdadb-f072-4dad-a404-8335c5960de3omero.api.ISession(omero.api._ISessionTie@2756814a)
2012-11-27 13:47:17,726 INFO  [                      omero.cmd.SessionI] (.Server-99) Removed servant from adapter: f9ffdadb-f072-4dad-a404-8335c5960de3omero.api.ISession
2012-11-27 13:47:17,732 INFO  [                      omero.cmd.SessionI] (.Server-98) Added servant to adapter: 0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f/650ca3f8-cb88-4930-abef-64964bdff995omero.api.IConfig(omero.api._IConfigTie@419e1e42)
2012-11-27 13:47:17,734 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Meth:   interface ome.api.IConfig.getConfigValue
2012-11-27 13:47:17,734 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Args:   [omero.version]
2012-11-27 13:47:17,744 INFO  [         ome.security.basic.EventHandler] (.Server-96)  Auth:   user=1,group=4,event=1214325(User),sess=0d8af8ca-ad08-45fc-8aa6-8c5efe147c3f
2012-11-27 13:47:17,746 INFO  [                 org.perf4j.TimingLogger] (.Server-96) start[1354045637734] time[12] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2012-11-27 13:47:17,746 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Rslt:   4.4.5-ice34-b20
2012-11-27 13:47:17,767 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.executeCheckPasswordRO(chris)
2012-11-27 13:47:17,767 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Args:   [null, InternalSF@479481162]
2012-11-27 13:47:17,769 INFO  [         ome.security.basic.EventHandler] (Server-100)  Auth:   user=0,group=0,event=null(Sessions),sess=e0937ca4-02ba-47b0-acc8-79e345e8fed1
2012-11-27 13:47:17,771 INFO  [                 org.perf4j.TimingLogger] (Server-100) start[1354045637767] time[4] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$8.doWork]
2012-11-27 13:47:17,771 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Rslt:   true
2012-11-27 13:47:17,772 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2012-11-27 13:47:17,772 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Args:   [null, InternalSF@479481162]
2012-11-27 13:47:17,783 INFO  [         ome.security.basic.EventHandler] (.Server-99)  Auth:   user=0,group=0,event=1214326(Sessions),sess=e0937ca4-02ba-47b0-acc8-79e345e8fed1
2012-11-27 13:47:17,792 INFO  [       ome.security.basic.CurrentDetails] (.Server-99) Adding log:INSERT,class ome.model.meta.Session,223566
2012-11-27 13:47:17,799 INFO  [                 org.perf4j.TimingLogger] (.Server-99) start[1354045637772] time[27] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2012-11-27 13:47:17,800 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Rslt:   (ome.model.meta.Experimenter:Id_1302, ome.model.meta.ExperimenterGroup:Id_4, (4, 1), ... 4 more)
2012-11-27 13:47:17,801 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-99) Created session ServiceFactoryI(session-4bdde727-7885-447c-997a-376fc940e3a9/9c053c0a-65d3-4a7a-958a-b144586232fb) for user chris (agent=OMERO.web)
2012-11-27 13:47:17,808 INFO  [                      omero.cmd.SessionI] (.Server-87) Added servant to adapter: 9c053c0a-65d3-4a7a-958a-b144586232fb/4bdde727-7885-447c-997a-376fc940e3a9omero.api.ISession(omero.api._ISessionTie@2f88277a)
2012-11-27 13:47:17,809 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Meth:   interface ome.api.ISession.getSession
2012-11-27 13:47:17,810 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Args:   [9c053c0a-65d3-4a7a-958a-b144586232fb]
2012-11-27 13:47:17,810 INFO  [                 org.perf4j.TimingLogger] (Server-100) start[1354045637810] time[0] tag[omero.call.success.ome.services.sessions.SessionBean.getSession]
2012-11-27 13:47:17,810 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Rslt:   ome.model.meta.Session:Id_223566
2012-11-27 13:47:17,816 INFO  [                      omero.cmd.SessionI] (.Server-99) Added servant to adapter: 9c053c0a-65d3-4a7a-958a-b144586232fb/4bdde727-7885-447c-997a-376fc940e3a9omero.api.IConfig(omero.api._IConfigTie@18089b98)
2012-11-27 13:47:17,818 INFO  [        ome.services.util.ServiceHandler] (.Server-98)  Meth:   interface ome.api.IConfig.getConfigValue
2012-11-27 13:47:17,818 INFO  [        ome.services.util.ServiceHandler] (.Server-98)  Args:   [omero.router.insecure]
2012-11-27 13:47:17,830 INFO  [         ome.security.basic.EventHandler] (.Server-98)  Auth:   user=1302,group=4,event=1214327(User),sess=9c053c0a-65d3-4a7a-958a-b144586232fb
2012-11-27 13:47:17,833 INFO  [                 org.perf4j.TimingLogger] (.Server-98) start[1354045637818] time[15] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2012-11-27 13:47:17,833 INFO  [        ome.services.util.ServiceHandler] (.Server-98)  Rslt:   OMERO.Glacier2/router:tcp -p 4063 -h @omero.host@
2012-11-27 13:47:17,842 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-87) Found session locally: 9c053c0a-65d3-4a7a-958a-b144586232fb
2012-11-27 13:47:17,843 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-87) Rejoining session ServiceFactoryI(session-9a73223b-7797-4abd-9128-45d5ed487a7d/9c053c0a-65d3-4a7a-958a-b144586232fb) (agent=OMERO.web;secure=False)
2012-11-27 13:47:17,847 INFO  [e.services.sessions.SessionContext$Count] (.Server-99) -Reference count: 9c053c0a-65d3-4a7a-958a-b144586232fb=1
2012-11-27 13:47:17,847 INFO  [                      omero.cmd.SessionI] (.Server-99) cleanupSelf(ServiceFactoryI(session-4bdde727-7885-447c-997a-376fc940e3a9/9c053c0a-65d3-4a7a-958a-b144586232fb)).
2012-11-27 13:47:17,847 INFO  [                      omero.cmd.SessionI] (.Server-99) Unregistered servant:9c053c0a-65d3-4a7a-958a-b144586232fb/4bdde727-7885-447c-997a-376fc940e3a9omero.api.ISession(omero.api._ISessionTie@2f88277a)
2012-11-27 13:47:17,847 INFO  [                      omero.cmd.SessionI] (.Server-99) Removed servant from adapter: 4bdde727-7885-447c-997a-376fc940e3a9omero.api.ISession
2012-11-27 13:47:17,847 INFO  [                      omero.cmd.SessionI] (.Server-99) Unregistered servant:9c053c0a-65d3-4a7a-958a-b144586232fb/4bdde727-7885-447c-997a-376fc940e3a9omero.api.IConfig(omero.api._IConfigTie@18089b98)
2012-11-27 13:47:17,847 INFO  [                      omero.cmd.SessionI] (.Server-99) Removed servant from adapter: 4bdde727-7885-447c-997a-376fc940e3a9omero.api.IConfig
2012-11-27 13:47:17,854 INFO  [                      omero.cmd.SessionI] (.Server-98) Added servant to adapter: 9c053c0a-65d3-4a7a-958a-b144586232fb/9a73223b-7797-4abd-9128-45d5ed487a7domero.api.IAdmin(omero.api._IAdminTie@406d2db7)
2012-11-27 13:47:17,855 INFO  [        ome.services.util.ServiceHandler] (.Server-87)  Meth:   interface ome.api.IAdmin.getEventContext
2012-11-27 13:47:17,855 INFO  [        ome.services.util.ServiceHandler] (.Server-87)  Args:   ()
2012-11-27 13:47:17,857 INFO  [         ome.security.basic.EventHandler] (.Server-87)  Auth:   user=1302,group=4,event=null(User),sess=9c053c0a-65d3-4a7a-958a-b144586232fb
2012-11-27 13:47:17,857 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(9c053c0a-65d3-4a7a-958a-b144586232fb)
2012-11-27 13:47:17,857 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Args:   [null, InternalSF@479481162]
2012-11-27 13:47:17,859 INFO  [         ome.security.basic.EventHandler] (2-thread-2)  Auth:   user=0,group=0,event=null(Sessions),sess=e0937ca4-02ba-47b0-acc8-79e345e8fed1
2012-11-27 13:47:17,864 INFO  [                 org.perf4j.TimingLogger] (2-thread-2) start[1354045637857] time[7] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2012-11-27 13:47:17,864 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Rslt:   (ome.model.meta.Experimenter:Id_1302, ome.model.meta.ExperimenterGroup:Id_4, (4, 1), ... 4 more)
2012-11-27 13:47:17,865 INFO  [                 org.perf4j.TimingLogger] (.Server-87) start[1354045637855] time[10] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2012-11-27 13:47:17,865 INFO  [        ome.services.util.ServiceHandler] (.Server-87)  Rslt:   ome.system.SimpleEventContext@58dfb77b
2012-11-27 13:47:17,867 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Meth:   interface ome.api.IAdmin.getSecurityRoles
2012-11-27 13:47:17,867 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Args:   ()
2012-11-27 13:47:17,868 INFO  [         ome.security.basic.EventHandler] (Server-100)  Auth:   user=1302,group=4,event=null(User),sess=9c053c0a-65d3-4a7a-958a-b144586232fb
2012-11-27 13:47:17,869 INFO  [                 org.perf4j.TimingLogger] (Server-100) start[1354045637867] time[2] tag[omero.call.success.ome.logic.AdminImpl.getSecurityRoles]
2012-11-27 13:47:17,869 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Rslt:   ome.system.Roles@4f65b474
2012-11-27 13:47:53,821 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-96) Found session locally: 316b0177-832e-4e3d-9455-585e19467420
2012-11-27 13:47:53,822 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-96) Rejoining session ServiceFactoryI(session-e90429de-148f-422a-b5cd-2cf74d9681b6/316b0177-832e-4e3d-9455-585e19467420) (agent=OMERO.web)
2012-11-27 13:47:53,831 INFO  [e.services.sessions.SessionContext$Count] (.Server-87) -Reference count: 316b0177-832e-4e3d-9455-585e19467420=0
2012-11-27 13:47:53,831 INFO  [                      omero.cmd.SessionI] (.Server-87) cleanupSelf(ServiceFactoryI(session-e90429de-148f-422a-b5cd-2cf74d9681b6/316b0177-832e-4e3d-9455-585e19467420)).
2012-11-27 13:47:59,022 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.executeCheckPasswordRO(guest)
2012-11-27 13:47:59,023 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Args:   [null, InternalSF@479481162]
2012-11-27 13:47:59,024 INFO  [         ome.security.basic.EventHandler] (.Server-99)  Auth:   user=0,group=0,event=null(Sessions),sess=e0937ca4-02ba-47b0-acc8-79e345e8fed1
2012-11-27 13:47:59,027 INFO  [                 org.perf4j.TimingLogger] (.Server-99) start[1354045679023] time[4] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$8.doWork]
2012-11-27 13:47:59,027 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Rslt:   true
2012-11-27 13:47:59,028 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2012-11-27 13:47:59,028 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Args:   [null, InternalSF@479481162]
2012-11-27 13:47:59,038 INFO  [         ome.security.basic.EventHandler] (.Server-96)  Auth:   user=0,group=0,event=1214328(Sessions),sess=e0937ca4-02ba-47b0-acc8-79e345e8fed1
2012-11-27 13:47:59,046 INFO  [       ome.security.basic.CurrentDetails] (.Server-96) Adding log:INSERT,class ome.model.meta.Session,223567
2012-11-27 13:47:59,056 INFO  [                 org.perf4j.TimingLogger] (.Server-96) start[1354045679028] time[28] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2012-11-27 13:47:59,056 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Rslt:   (ome.model.meta.Experimenter:Id_1, ome.model.meta.ExperimenterGroup:Id_4, (4, 2), ... 4 more)
2012-11-27 13:47:59,057 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-96) Created session ServiceFactoryI(session-7aa95756-5935-4cd7-a7d0-b6e309bbbed2/16c495b9-1532-490f-92de-aa961efcc871) for user guest (agent=OMERO.web)
2012-11-27 13:47:59,065 INFO  [                      omero.cmd.SessionI] (Server-100) Added servant to adapter: 16c495b9-1532-490f-92de-aa961efcc871/7aa95756-5935-4cd7-a7d0-b6e309bbbed2omero.api.ISession(omero.api._ISessionTie@51ffc765)
2012-11-27 13:47:59,066 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Meth:   interface ome.api.ISession.getSession
2012-11-27 13:47:59,066 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Args:   [16c495b9-1532-490f-92de-aa961efcc871]
2012-11-27 13:47:59,067 INFO  [                 org.perf4j.TimingLogger] (.Server-99) start[1354045679067] time[0] tag[omero.call.success.ome.services.sessions.SessionBean.getSession]
2012-11-27 13:47:59,067 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Rslt:   ome.model.meta.Session:Id_223567
2012-11-27 13:47:59,073 INFO  [                      omero.cmd.SessionI] (.Server-96) Added servant to adapter: 16c495b9-1532-490f-92de-aa961efcc871/7aa95756-5935-4cd7-a7d0-b6e309bbbed2omero.api.IConfig(omero.api._IConfigTie@876c08e1)
2012-11-27 13:47:59,075 INFO  [        ome.services.util.ServiceHandler] (.Server-98)  Meth:   interface ome.api.IConfig.getConfigValue
2012-11-27 13:47:59,075 INFO  [        ome.services.util.ServiceHandler] (.Server-98)  Args:   [omero.router.insecure]
2012-11-27 13:47:59,085 INFO  [         ome.security.basic.EventHandler] (.Server-98)  Auth:   user=1,group=4,event=1214329(User),sess=16c495b9-1532-490f-92de-aa961efcc871
2012-11-27 13:47:59,088 INFO  [                 org.perf4j.TimingLogger] (.Server-98) start[1354045679075] time[13] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2012-11-27 13:47:59,088 INFO  [        ome.services.util.ServiceHandler] (.Server-98)  Rslt:   OMERO.Glacier2/router:tcp -p 4063 -h @omero.host@
2012-11-27 13:47:59,094 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-100) Found session locally: 16c495b9-1532-490f-92de-aa961efcc871
2012-11-27 13:47:59,095 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-100) Rejoining session ServiceFactoryI(session-c42c6295-77b2-4682-a3c4-e7bb85978a17/16c495b9-1532-490f-92de-aa961efcc871) (agent=OMERO.web;secure=False)
2012-11-27 13:47:59,098 INFO  [e.services.sessions.SessionContext$Count] (.Server-96) -Reference count: 16c495b9-1532-490f-92de-aa961efcc871=1
2012-11-27 13:47:59,098 INFO  [                      omero.cmd.SessionI] (.Server-96) cleanupSelf(ServiceFactoryI(session-7aa95756-5935-4cd7-a7d0-b6e309bbbed2/16c495b9-1532-490f-92de-aa961efcc871)).
2012-11-27 13:47:59,098 INFO  [                      omero.cmd.SessionI] (.Server-96) Unregistered servant:16c495b9-1532-490f-92de-aa961efcc871/7aa95756-5935-4cd7-a7d0-b6e309bbbed2omero.api.ISession(omero.api._ISessionTie@51ffc765)
2012-11-27 13:47:59,098 INFO  [                      omero.cmd.SessionI] (.Server-96) Removed servant from adapter: 7aa95756-5935-4cd7-a7d0-b6e309bbbed2omero.api.ISession
2012-11-27 13:47:59,098 INFO  [                      omero.cmd.SessionI] (.Server-96) Unregistered servant:16c495b9-1532-490f-92de-aa961efcc871/7aa95756-5935-4cd7-a7d0-b6e309bbbed2omero.api.IConfig(omero.api._IConfigTie@876c08e1)
2012-11-27 13:47:59,098 INFO  [                      omero.cmd.SessionI] (.Server-96) Removed servant from adapter: 7aa95756-5935-4cd7-a7d0-b6e309bbbed2omero.api.IConfig
2012-11-27 13:47:59,104 INFO  [                      omero.cmd.SessionI] (.Server-87) Added servant to adapter: 16c495b9-1532-490f-92de-aa961efcc871/c42c6295-77b2-4682-a3c4-e7bb85978a17omero.api.IConfig(omero.api._IConfigTie@1b060f99)
2012-11-27 13:47:59,106 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Meth:   interface ome.api.IConfig.getConfigValue
2012-11-27 13:47:59,106 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Args:   [omero.version]
2012-11-27 13:47:59,116 INFO  [         ome.security.basic.EventHandler] (Server-100)  Auth:   user=1,group=4,event=1214330(User),sess=16c495b9-1532-490f-92de-aa961efcc871
2012-11-27 13:47:59,118 INFO  [                 org.perf4j.TimingLogger] (Server-100) start[1354045679106] time[12] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2012-11-27 13:47:59,119 INFO  [        ome.services.util.ServiceHandler] (Server-100)  Rslt:   4.4.5-ice34-b20
2012-11-27 13:47:59,139 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.executeCheckPasswordRO(chris)
2012-11-27 13:47:59,139 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Args:   [null, InternalSF@479481162]
2012-11-27 13:47:59,141 INFO  [         ome.security.basic.EventHandler] (.Server-99)  Auth:   user=0,group=0,event=null(Sessions),sess=e0937ca4-02ba-47b0-acc8-79e345e8fed1
2012-11-27 13:47:59,143 INFO  [                 org.perf4j.TimingLogger] (.Server-99) start[1354045679139] time[4] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$8.doWork]
2012-11-27 13:47:59,143 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Rslt:   true
2012-11-27 13:47:59,144 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2012-11-27 13:47:59,144 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Args:   [null, InternalSF@479481162]
2012-11-27 13:47:59,153 INFO  [         ome.security.basic.EventHandler] (.Server-96)  Auth:   user=0,group=0,event=1214331(Sessions),sess=e0937ca4-02ba-47b0-acc8-79e345e8fed1
2012-11-27 13:47:59,161 INFO  [       ome.security.basic.CurrentDetails] (.Server-96) Adding log:INSERT,class ome.model.meta.Session,223568
2012-11-27 13:47:59,168 INFO  [                 org.perf4j.TimingLogger] (.Server-96) start[1354045679144] time[24] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2012-11-27 13:47:59,168 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Rslt:   (ome.model.meta.Experimenter:Id_1302, ome.model.meta.ExperimenterGroup:Id_4, (4, 1), ... 4 more)
2012-11-27 13:47:59,169 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-96) Created session ServiceFactoryI(session-30f82c77-8607-4b15-866f-0d8ac1f4f08d/db697a64-7b68-4ef6-a442-b8c56fafe7b8) for user chris (agent=OMERO.web)
2012-11-27 13:47:59,176 INFO  [                      omero.cmd.SessionI] (.Server-87) Added servant to adapter: db697a64-7b68-4ef6-a442-b8c56fafe7b8/30f82c77-8607-4b15-866f-0d8ac1f4f08domero.api.ISession(omero.api._ISessionTie@8409a30a)
2012-11-27 13:47:59,177 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Meth:   interface ome.api.ISession.getSession
2012-11-27 13:47:59,177 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Args:   [db697a64-7b68-4ef6-a442-b8c56fafe7b8]
2012-11-27 13:47:59,177 INFO  [                 org.perf4j.TimingLogger] (.Server-99) start[1354045679177] time[0] tag[omero.call.success.ome.services.sessions.SessionBean.getSession]
2012-11-27 13:47:59,177 INFO  [        ome.services.util.ServiceHandler] (.Server-99)  Rslt:   ome.model.meta.Session:Id_223568
2012-11-27 13:47:59,185 INFO  [                      omero.cmd.SessionI] (.Server-96) Added servant to adapter: db697a64-7b68-4ef6-a442-b8c56fafe7b8/30f82c77-8607-4b15-866f-0d8ac1f4f08domero.api.IConfig(omero.api._IConfigTie@32453efa)
2012-11-27 13:47:59,187 INFO  [        ome.services.util.ServiceHandler] (.Server-98)  Meth:   interface ome.api.IConfig.getConfigValue
2012-11-27 13:47:59,187 INFO  [        ome.services.util.ServiceHandler] (.Server-98)  Args:   [omero.router.insecure]
2012-11-27 13:47:59,197 INFO  [         ome.security.basic.EventHandler] (.Server-98)  Auth:   user=1302,group=4,event=1214332(User),sess=db697a64-7b68-4ef6-a442-b8c56fafe7b8
2012-11-27 13:47:59,199 INFO  [                 org.perf4j.TimingLogger] (.Server-98) start[1354045679187] time[12] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2012-11-27 13:47:59,199 INFO  [        ome.services.util.ServiceHandler] (.Server-98)  Rslt:   OMERO.Glacier2/router:tcp -p 4063 -h @omero.host@
2012-11-27 13:47:59,207 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-87) Found session locally: db697a64-7b68-4ef6-a442-b8c56fafe7b8
2012-11-27 13:47:59,208 INFO  [ ome.services.blitz.fire.SessionManagerI] (.Server-87) Rejoining session ServiceFactoryI(session-b8d81a9b-a7e0-48e4-a655-f84dc108f1da/db697a64-7b68-4ef6-a442-b8c56fafe7b8) (agent=OMERO.web;secure=False)
2012-11-27 13:47:59,212 INFO  [e.services.sessions.SessionContext$Count] (.Server-99) -Reference count: db697a64-7b68-4ef6-a442-b8c56fafe7b8=1
2012-11-27 13:47:59,212 INFO  [                      omero.cmd.SessionI] (.Server-99) cleanupSelf(ServiceFactoryI(session-30f82c77-8607-4b15-866f-0d8ac1f4f08d/db697a64-7b68-4ef6-a442-b8c56fafe7b8)).
2012-11-27 13:47:59,212 INFO  [                      omero.cmd.SessionI] (.Server-99) Unregistered servant:db697a64-7b68-4ef6-a442-b8c56fafe7b8/30f82c77-8607-4b15-866f-0d8ac1f4f08domero.api.ISession(omero.api._ISessionTie@8409a30a)
2012-11-27 13:47:59,212 INFO  [                      omero.cmd.SessionI] (.Server-99) Removed servant from adapter: 30f82c77-8607-4b15-866f-0d8ac1f4f08domero.api.ISession
2012-11-27 13:47:59,212 INFO  [                      omero.cmd.SessionI] (.Server-99) Unregistered servant:db697a64-7b68-4ef6-a442-b8c56fafe7b8/30f82c77-8607-4b15-866f-0d8ac1f4f08domero.api.IConfig(omero.api._IConfigTie@32453efa)
2012-11-27 13:47:59,212 INFO  [                      omero.cmd.SessionI] (.Server-99) Removed servant from adapter: 30f82c77-8607-4b15-866f-0d8ac1f4f08domero.api.IConfig
2012-11-27 13:47:59,219 INFO  [                      omero.cmd.SessionI] (.Server-98) Added servant to adapter: db697a64-7b68-4ef6-a442-b8c56fafe7b8/b8d81a9b-a7e0-48e4-a655-f84dc108f1daomero.api.IAdmin(omero.api._IAdminTie@6bee0f4f)
2012-11-27 13:47:59,220 INFO  [        ome.services.util.ServiceHandler] (.Server-87)  Meth:   interface ome.api.IAdmin.getEventContext
2012-11-27 13:47:59,220 INFO  [        ome.services.util.ServiceHandler] (.Server-87)  Args:   ()
2012-11-27 13:47:59,222 INFO  [         ome.security.basic.EventHandler] (.Server-87)  Auth:   user=1302,group=4,event=null(User),sess=db697a64-7b68-4ef6-a442-b8c56fafe7b8
2012-11-27 13:47:59,222 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(db697a64-7b68-4ef6-a442-b8c56fafe7b8)
2012-11-27 13:47:59,222 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Args:   [null, InternalSF@479481162]
2012-11-27 13:47:59,223 INFO  [         ome.security.basic.EventHandler] (2-thread-3)  Auth:   user=0,group=0,event=null(Sessions),sess=e0937ca4-02ba-47b0-acc8-79e345e8fed1
2012-11-27 13:47:59,228 INFO  [                 org.perf4j.TimingLogger] (2-thread-3) start[1354045679222] time[6] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2012-11-27 13:47:59,228 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Rslt:   (ome.model.meta.Experimenter:Id_1302, ome.model.meta.ExperimenterGroup:Id_4, (4, 1), ... 4 more)
2012-11-27 13:47:59,229 INFO  [                 org.perf4j.TimingLogger] (.Server-87) start[1354045679220] time[9] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2012-11-27 13:47:59,229 INFO  [        ome.services.util.ServiceHandler] (.Server-87)  Rslt:   ome.system.SimpleEventContext@7ece26b
2012-11-27 13:47:59,231 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Meth:   interface ome.api.IAdmin.getSecurityRoles
2012-11-27 13:47:59,231 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Args:   ()
2012-11-27 13:47:59,232 INFO  [         ome.security.basic.EventHandler] (.Server-96)  Auth:   user=1302,group=4,event=null(User),sess=db697a64-7b68-4ef6-a442-b8c56fafe7b8
2012-11-27 13:47:59,233 INFO  [                 org.perf4j.TimingLogger] (.Server-96) start[1354045679231] time[2] tag[omero.call.success.ome.logic.AdminImpl.getSecurityRoles]
2012-11-27 13:47:59,233 INFO  [        ome.services.util.ServiceHandler] (.Server-96)  Rslt:   ome.system.Roles@4f65b474


[cxallan]

All I can think of at this point is that there is something hanging somewhere. There's nothing untoward in master.err or master.out?

[chriswood]

I didn't see anything in the master.err or master.log files. I did notice that entering the wrong password returns very quickly with a password error.

Chris

[albot]

Hi

This behavior rings a bell and I digged back into my email with Raf from our IT department.

Around July 2012 we had similar issues with 4.3.X running on a Ubuntu 10.04 system.

As far as I see we upgraded the installation to Ubuntu 12.04 at the very end.

Raf found out that the kernel from 10.04 reported bugs with the following message
BUG: soft lockup - CPU#0 stuck for 30s [java]
BUG: soft lockup - CPU#0 stuck for 42s [postgres]
etc

I do not know whether this might help you to find the source of the issue but just letting you know.

reference https://www.openmicroscopy.org/community/viewtopic.php?f=5&t=1200

Cheers
Alex