Exception in thread "Initializer"

[davemason]

Hello all,

Great to see 5.0.3, so thanks to the team for getting that out. I updated over the weekend and though everything seemed fine, I had some users today not be able to connect.

Oddly, connection through the web interface works, but no connection can be made through insight (5.0.2, or 5.0.3 clients). In live tests (watching the Blitz log), nothing appeared in the log during an insight login. On the client side the log (attached) seems to be throwing errors but to me it might as well be vulcan.

Short version;

Code: Select all

Reason: Can't connect to OMERO. OMERO info not valid.Ice.ConnectionLostException

Any thoughts would be appreciated,

Dave

Code: Select all

2014-08-11 13:40:35,221 INFO  [o.o.shoola.env.rnd.PixelsServicesFactory] (nitializer) Heap memory usage: max 1037959168
2014-08-11 13:40:35,252 INFO  [         o.o.shoola.env.init.TaskBarInit] (nitializer) Loaded L&F: com.sun.java.swing.plaf.windows.WindowsLookAndFeel
2014-08-11 13:40:43,427 DEBUG [   o.o.s.env.data.login.LoginServiceImpl] (nitializer) Failed to log onto OMERO.
Reason: Can't connect to OMERO. OMERO info not valid.

Ice.ConnectionLostException
    error = 0
   at IceInternal.ConnectRequestHandler.getConnection(ConnectRequestHandler.java:244)
   at IceInternal.ConnectRequestHandler.sendRequest(ConnectRequestHandler.java:141)
   at IceInternal.Outgoing.invoke(Outgoing.java:77)
   at Ice._ObjectDelM.ice_isA(_ObjectDelM.java:33)
   at Ice.ObjectPrxHelperBase.ice_isA(ObjectPrxHelperBase.java:98)
   at Ice.ObjectPrxHelperBase.ice_isA(ObjectPrxHelperBase.java:61)
   at Glacier2.RouterPrxHelper.checkedCast(RouterPrxHelper.java:2262)
   at omero.client.getRouter(client.java:770)
   at omero.client.createSession(client.java:693)
   at org.openmicroscopy.shoola.env.data.OMEROGateway.createSession(OMEROGateway.java:1831)
   at org.openmicroscopy.shoola.env.data.DataServicesFactory.connect(DataServicesFactory.java:590)
   at org.openmicroscopy.shoola.env.data.login.LoginServiceImpl.attempt(LoginServiceImpl.java:136)
   at org.openmicroscopy.shoola.env.data.login.LoginServiceImpl.login(LoginServiceImpl.java:265)
   at org.openmicroscopy.shoola.env.data.login.LoginManager.login(LoginManager.java:98)
   at org.openmicroscopy.shoola.env.init.SplashScreenInit.onEnd(SplashScreenInit.java:169)
   at org.openmicroscopy.shoola.env.init.Initializer.notifyEnd(Initializer.java:189)
   at org.openmicroscopy.shoola.env.Container.runStartupProcedure(Container.java:129)
   at org.openmicroscopy.shoola.env.Container.access$000(Container.java:78)
   at org.openmicroscopy.shoola.env.Container$1.run(Container.java:174)
   at java.lang.Thread.run(Unknown Source)

OMERO address: cci02.liv.ac.uk
User Name: dnmason -- Password: ************
org.openmicroscopy.shoola.env.data.DSOutOfServiceException: Can't connect to OMERO. OMERO info not valid.

Ice.ConnectionLostException
    error = 0
   at IceInternal.ConnectRequestHandler.getConnection(ConnectRequestHandler.java:244)
   at IceInternal.ConnectRequestHandler.sendRequest(ConnectRequestHandler.java:141)
   at IceInternal.Outgoing.invoke(Outgoing.java:77)
   at Ice._ObjectDelM.ice_isA(_ObjectDelM.java:33)
   at Ice.ObjectPrxHelperBase.ice_isA(ObjectPrxHelperBase.java:98)
   at Ice.ObjectPrxHelperBase.ice_isA(ObjectPrxHelperBase.java:61)
   at Glacier2.RouterPrxHelper.checkedCast(RouterPrxHelper.java:2262)
   at omero.client.getRouter(client.java:770)
   at omero.client.createSession(client.java:693)
   at org.openmicroscopy.shoola.env.data.OMEROGateway.createSession(OMEROGateway.java:1831)
   at org.openmicroscopy.shoola.env.data.DataServicesFactory.connect(DataServicesFactory.java:590)
   at org.openmicroscopy.shoola.env.data.login.LoginServiceImpl.attempt(LoginServiceImpl.java:136)
   at org.openmicroscopy.shoola.env.data.login.LoginServiceImpl.login(LoginServiceImpl.java:265)
   at org.openmicroscopy.shoola.env.data.login.LoginManager.login(LoginManager.java:98)
   at org.openmicroscopy.shoola.env.init.SplashScreenInit.onEnd(SplashScreenInit.java:169)
   at org.openmicroscopy.shoola.env.init.Initializer.notifyEnd(Initializer.java:189)
   at org.openmicroscopy.shoola.env.Container.runStartupProcedure(Container.java:129)
   at org.openmicroscopy.shoola.env.Container.access$000(Container.java:78)
   at org.openmicroscopy.shoola.env.Container$1.run(Container.java:174)
   at java.lang.Thread.run(Unknown Source)

   at org.openmicroscopy.shoola.env.data.OMEROGateway.createSession(OMEROGateway.java:1850)
   at org.openmicroscopy.shoola.env.data.DataServicesFactory.connect(DataServicesFactory.java:590)
   at org.openmicroscopy.shoola.env.data.login.LoginServiceImpl.attempt(LoginServiceImpl.java:136)
   at org.openmicroscopy.shoola.env.data.login.LoginServiceImpl.login(LoginServiceImpl.java:265)
   at org.openmicroscopy.shoola.env.data.login.LoginManager.login(LoginManager.java:98)
   at org.openmicroscopy.shoola.env.init.SplashScreenInit.onEnd(SplashScreenInit.java:169)
   at org.openmicroscopy.shoola.env.init.Initializer.notifyEnd(Initializer.java:189)
   at org.openmicroscopy.shoola.env.Container.runStartupProcedure(Container.java:129)
   at org.openmicroscopy.shoola.env.Container.access$000(Container.java:78)
   at org.openmicroscopy.shoola.env.Container$1.run(Container.java:174)
   at java.lang.Thread.run(Unknown Source)
Caused by: Ice.ConnectionLostException
    error = 0
   at IceInternal.ConnectRequestHandler.getConnection(ConnectRequestHandler.java:244)
   at IceInternal.ConnectRequestHandler.sendRequest(ConnectRequestHandler.java:141)
   at IceInternal.Outgoing.invoke(Outgoing.java:77)
   at Ice._ObjectDelM.ice_isA(_ObjectDelM.java:33)
   at Ice.ObjectPrxHelperBase.ice_isA(ObjectPrxHelperBase.java:98)
   at Ice.ObjectPrxHelperBase.ice_isA(ObjectPrxHelperBase.java:61)
   at Glacier2.RouterPrxHelper.checkedCast(RouterPrxHelper.java:2262)
   at omero.client.getRouter(client.java:770)
   at omero.client.createSession(client.java:693)
   at org.openmicroscopy.shoola.env.data.OMEROGateway.createSession(OMEROGateway.java:1831)
   ... 10 more
Failed to log onto OMERO.
Reason: Can't connect to OMERO. OMERO info not valid.

etc etc ...

Exception in thread "Initializer"



[manics]

Hi Dave

Is it possible your server's network or firewall configuration was changed? Can you check ports 4063 and 4064 are definitely accessible from outside? Are there any warnings or errors in Blitz*.log, master.err or master.out from when the server started up?

Thanks, Simon

[davemason]

Hi Simon,

Thanks for the quick reply. Nothing abnormal as far as i can tell in the logs on startup. Certainly no warnings.

It could well be that our IT guys have changed up something on the network. More worrying is that I rolled back to 5.0.2 hoping for a fix and am experiencing the same thing. At least I know it's not 5.0.3 specific!

I'll look into the network issues, but in the meantime, is there an easy way to uninstall clients from a computer. It feels like there's some config file or setting somewhere that is screwing with my client connections.

Cheers,

Dave

[davemason]

Simon,

As far as I can tell, ports 4063 and 4064 are accessible. Running an nmap scan on these ports gives me:

Code: Select all

PORT     STATE SERVICE    VERSION
4063/tcp open  ice        Internet Communications Engine
4064/tcp open  tcpwrapped

Would port accessibility explain why I can login via a webclient but not Insight? Upon a failed login, I don't even get any activity in the Blitz log so I agree it seems to be an issue in initial connection but I have no idea where to go from here. Once again, web access seems to work fine.

[manics]

Hi Dave

If your OMERO server is in the standard configuration OMERO.web will be connecting internally to OMERO.server via 4063/4064 so only port 80 needs to be externally accessible to use the web client. If 4063/4064 were blocked from outside access this would explain why other clients might be unable to connect.

When you login to OMERO.web do you see any messages in Blitz.log?

[davemason]

Thanks for the clarification on ports. Our is a pretty vanilla OMERO setup on Ubuntu 12.04 LTS. Computer services claim to have not changed anything on the infrastructure side.

When connecting via web I just get INFO lines in the log. To get the following, I tailed the Blitz log into a file, then did a login and logout through the webclient.

Code: Select all

2014-08-12 11:45:00,019 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-5) Performing requestHeartbeats
2014-08-12 11:46:51,973 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.executeCheckPasswordRO(guest)
2014-08-12 11:46:51,973 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:51,978 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:51,984 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840411974] time[10] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$8.doWork]
2014-08-12 11:46:51,984 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   true
2014-08-12 11:46:51,986 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2014-08-12 11:46:51,986 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:51,991 INFO  [    ome.security.basic.BasicEventContext] (Server-639)  cctx:   group=0
2014-08-12 11:46:52,056 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=0,group=0,event=136781(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:52,067 INFO  [       ome.security.basic.CurrentDetails] (Server-639) Adding log:INSERT,class ome.model.meta.Session,3953
2014-08-12 11:46:52,084 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840411986] time[98] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2014-08-12 11:46:52,084 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   (ome.model.meta.Experimenter:Id_1, ome.model.meta.ExperimenterGroup:Id_2, (2), ... 4 more)
2014-08-12 11:46:52,089 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-639) Created session ServiceFactoryI(session-01d54cc2-4bfc-4b52-b362-ce6bb10d2341/22ee5c5f-3863-485d-9fe3-d8107c5eae23) for user guest (agent=OMERO.web)
2014-08-12 11:46:52,099 INFO  [                      omero.cmd.SessionI] (Server-637) Added servant to adapter: 22ee5c5f-3863-485d-9fe3-d8107c5eae23/01d54cc2-4bfc-4b52-b362-ce6bb10d2341omero.api.ISession(omero.api._ISessionTie@329685d4)
2014-08-12 11:46:52,101 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.ISession.getSession
2014-08-12 11:46:52,102 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [22ee5c5f-3863-485d-9fe3-d8107c5eae23]
2014-08-12 11:46:52,102 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840412102] time[0] tag[omero.call.success.ome.services.sessions.SessionBean.getSession]
2014-08-12 11:46:52,102 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   ome.model.meta.Session:Id_3953
2014-08-12 11:46:52,114 INFO  [                      omero.cmd.SessionI] (Server-637) Added servant to adapter: 22ee5c5f-3863-485d-9fe3-d8107c5eae23/01d54cc2-4bfc-4b52-b362-ce6bb10d2341omero.api.IConfig(omero.api._IConfigTie@856c3e5b)
2014-08-12 11:46:52,116 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IConfig.getConfigValue
2014-08-12 11:46:52,117 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [omero.router.insecure]
2014-08-12 11:46:52,135 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=1,group=2,event=136782(User),sess=22ee5c5f-3863-485d-9fe3-d8107c5eae23
2014-08-12 11:46:52,139 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840412117] time[22] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2014-08-12 11:46:52,139 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   OMERO.Glacier2/router:tcp -p 4063 -h @omero.host@
2014-08-12 11:46:52,146 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-639) Found session locally: 22ee5c5f-3863-485d-9fe3-d8107c5eae23
2014-08-12 11:46:52,147 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-639) Rejoining session ServiceFactoryI(session-bd3e35ed-f53b-4c35-a1e1-2dbf8f0a5378/22ee5c5f-3863-485d-9fe3-d8107c5eae23) (agent=OMERO.web;secure=False)
2014-08-12 11:46:52,152 INFO  [o.services.sessions.SessionContext$Count] (Server-639) -Reference count: 22ee5c5f-3863-485d-9fe3-d8107c5eae23=1
2014-08-12 11:46:52,152 INFO  [                      omero.cmd.SessionI] (Server-639) cleanupSelf(ServiceFactoryI(session-01d54cc2-4bfc-4b52-b362-ce6bb10d2341/22ee5c5f-3863-485d-9fe3-d8107c5eae23)).
2014-08-12 11:46:52,153 INFO  [                      omero.cmd.SessionI] (Server-639) Unregistered servant:22ee5c5f-3863-485d-9fe3-d8107c5eae23/01d54cc2-4bfc-4b52-b362-ce6bb10d2341omero.api.ISession(omero.api._ISessionTie@329685d4)
2014-08-12 11:46:52,153 INFO  [                      omero.cmd.SessionI] (Server-639) Removed servant from adapter: 01d54cc2-4bfc-4b52-b362-ce6bb10d2341omero.api.ISession
2014-08-12 11:46:52,153 INFO  [                      omero.cmd.SessionI] (Server-639) Unregistered servant:22ee5c5f-3863-485d-9fe3-d8107c5eae23/01d54cc2-4bfc-4b52-b362-ce6bb10d2341omero.api.IConfig(omero.api._IConfigTie@856c3e5b)
2014-08-12 11:46:52,153 INFO  [                      omero.cmd.SessionI] (Server-639) Removed servant from adapter: 01d54cc2-4bfc-4b52-b362-ce6bb10d2341omero.api.IConfig
2014-08-12 11:46:52,159 INFO  [                      omero.cmd.SessionI] (Server-639) Added servant to adapter: 22ee5c5f-3863-485d-9fe3-d8107c5eae23/bd3e35ed-f53b-4c35-a1e1-2dbf8f0a5378omero.api.IConfig(omero.api._IConfigTie@3cd9b291)
2014-08-12 11:46:52,161 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IConfig.getConfigValue
2014-08-12 11:46:52,162 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [omero.version]
2014-08-12 11:46:52,183 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=1,group=2,event=136783(User),sess=22ee5c5f-3863-485d-9fe3-d8107c5eae23
2014-08-12 11:46:52,188 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840412162] time[25] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2014-08-12 11:46:52,188 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   5.0.3-ice34-b41
2014-08-12 11:46:52,205 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.executeCheckPasswordRO(dnmason)
2014-08-12 11:46:52,205 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:52,208 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:53,071 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840412205] time[865] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$8.doWork]
2014-08-12 11:46:53,071 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   true
2014-08-12 11:46:53,073 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2014-08-12 11:46:53,073 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:53,076 INFO  [    ome.security.basic.BasicEventContext] (Server-637)  cctx:   group=0
2014-08-12 11:46:53,091 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=0,group=0,event=136784(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:53,104 INFO  [       ome.security.basic.CurrentDetails] (Server-637) Adding log:INSERT,class ome.model.meta.Session,3954
2014-08-12 11:46:53,120 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840413073] time[46] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2014-08-12 11:46:53,120 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   (ome.model.meta.Experimenter:Id_2, ome.model.meta.ExperimenterGroup:Id_53, (53, 1, 0, ... 1 more), ... 4 more)
2014-08-12 11:46:53,122 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-637) Created session ServiceFactoryI(session-77df6000-f057-44af-884a-2753677425cc/6372e1fd-0d82-4073-b28e-8636348b1a49) for user dnmason (agent=OMERO.web)
2014-08-12 11:46:53,130 INFO  [                      omero.cmd.SessionI] (Server-639) Added servant to adapter: 6372e1fd-0d82-4073-b28e-8636348b1a49/77df6000-f057-44af-884a-2753677425ccomero.api.ISession(omero.api._ISessionTie@287c7f49)
2014-08-12 11:46:53,132 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.ISession.getSession
2014-08-12 11:46:53,132 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [6372e1fd-0d82-4073-b28e-8636348b1a49]
2014-08-12 11:46:53,132 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840413132] time[0] tag[omero.call.success.ome.services.sessions.SessionBean.getSession]
2014-08-12 11:46:53,132 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   ome.model.meta.Session:Id_3954
2014-08-12 11:46:53,141 INFO  [                      omero.cmd.SessionI] (Server-639) Added servant to adapter: 6372e1fd-0d82-4073-b28e-8636348b1a49/77df6000-f057-44af-884a-2753677425ccomero.api.IConfig(omero.api._IConfigTie@599d4e96)
2014-08-12 11:46:53,143 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IConfig.getConfigValue
2014-08-12 11:46:53,143 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [omero.router.insecure]
2014-08-12 11:46:53,159 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=53,event=136785(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:53,162 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840413144] time[18] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2014-08-12 11:46:53,162 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   OMERO.Glacier2/router:tcp -p 4063 -h @omero.host@
2014-08-12 11:46:53,166 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-637) Found session locally: 6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:53,169 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-637) Rejoining session ServiceFactoryI(session-5dfc7fbf-ffae-4e6f-8e03-acbf889f7a93/6372e1fd-0d82-4073-b28e-8636348b1a49) (agent=OMERO.web;secure=False)
2014-08-12 11:46:53,173 INFO  [o.services.sessions.SessionContext$Count] (Server-637) -Reference count: 6372e1fd-0d82-4073-b28e-8636348b1a49=1
2014-08-12 11:46:53,173 INFO  [                      omero.cmd.SessionI] (Server-637) cleanupSelf(ServiceFactoryI(session-77df6000-f057-44af-884a-2753677425cc/6372e1fd-0d82-4073-b28e-8636348b1a49)).
2014-08-12 11:46:53,173 INFO  [                      omero.cmd.SessionI] (Server-637) Unregistered servant:6372e1fd-0d82-4073-b28e-8636348b1a49/77df6000-f057-44af-884a-2753677425ccomero.api.ISession(omero.api._ISessionTie@287c7f49)
2014-08-12 11:46:53,174 INFO  [                      omero.cmd.SessionI] (Server-637) Removed servant from adapter: 77df6000-f057-44af-884a-2753677425ccomero.api.ISession
2014-08-12 11:46:53,174 INFO  [                      omero.cmd.SessionI] (Server-637) Unregistered servant:6372e1fd-0d82-4073-b28e-8636348b1a49/77df6000-f057-44af-884a-2753677425ccomero.api.IConfig(omero.api._IConfigTie@599d4e96)
2014-08-12 11:46:53,174 INFO  [                      omero.cmd.SessionI] (Server-637) Removed servant from adapter: 77df6000-f057-44af-884a-2753677425ccomero.api.IConfig
2014-08-12 11:46:53,182 INFO  [                      omero.cmd.SessionI] (Server-637) Added servant to adapter: 6372e1fd-0d82-4073-b28e-8636348b1a49/5dfc7fbf-ffae-4e6f-8e03-acbf889f7a93omero.api.IAdmin(omero.api._IAdminTie@85dfcbec)
2014-08-12 11:46:53,184 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IAdmin.getEventContext
2014-08-12 11:46:53,184 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   ()
2014-08-12 11:46:53,187 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:53,188 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(6372e1fd-0d82-4073-b28e-8636348b1a49)
2014-08-12 11:46:53,188 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:53,200 INFO  [         ome.security.basic.EventHandler] (3-thread-8)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:53,213 INFO  [                 org.perf4j.TimingLogger] (3-thread-8) start[1407840413188] time[24] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2014-08-12 11:46:53,214 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Rslt:   (ome.model.meta.Experimenter:Id_2, ome.model.meta.ExperimenterGroup:Id_53, (53, 1, 0, ... 1 more), ... 4 more)
2014-08-12 11:46:53,215 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840413184] time[31] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2014-08-12 11:46:53,216 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   ome.system.SimpleEventContext@f3616e
2014-08-12 11:46:53,218 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IAdmin.getSecurityRoles
2014-08-12 11:46:53,218 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   ()
2014-08-12 11:46:53,221 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:53,222 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840413218] time[4] tag[omero.call.success.ome.logic.AdminImpl.getSecurityRoles]
2014-08-12 11:46:53,223 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   ome.system.Roles@101433d0
2014-08-12 11:46:54,520 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-637) Found session locally: 6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,523 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-637) Rejoining session ServiceFactoryI(session-95257f73-f80d-4ad7-8ef5-3e712bb5a763/6372e1fd-0d82-4073-b28e-8636348b1a49) (agent=OMERO.web)
2014-08-12 11:46:54,537 INFO  [                      omero.cmd.SessionI] (Server-639) Added servant to adapter: 6372e1fd-0d82-4073-b28e-8636348b1a49/95257f73-f80d-4ad7-8ef5-3e712bb5a763omero.api.IAdmin(omero.api._IAdminTie@136141f4)
2014-08-12 11:46:54,540 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IAdmin.getEventContext
2014-08-12 11:46:54,540 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   ()
2014-08-12 11:46:54,544 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,545 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(6372e1fd-0d82-4073-b28e-8636348b1a49)
2014-08-12 11:46:54,545 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:54,548 INFO  [         ome.security.basic.EventHandler] (3-thread-8)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:54,559 INFO  [                 org.perf4j.TimingLogger] (3-thread-8) start[1407840414545] time[13] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2014-08-12 11:46:54,559 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Rslt:   (ome.model.meta.Experimenter:Id_2, ome.model.meta.ExperimenterGroup:Id_53, (53, 1, 0, ... 1 more), ... 4 more)
2014-08-12 11:46:54,560 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840414540] time[20] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2014-08-12 11:46:54,561 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   ome.system.SimpleEventContext@65e074b
2014-08-12 11:46:54,566 INFO  [                      omero.cmd.SessionI] (Server-639) Added servant to adapter: 6372e1fd-0d82-4073-b28e-8636348b1a49/95257f73-f80d-4ad7-8ef5-3e712bb5a763omero.api.IQuery(omero.api._IQueryTie@815a32c7)
2014-08-12 11:46:54,569 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IQuery.findByQuery
2014-08-12 11:46:54,569 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [select distinct obj from ExperimenterGroup as obj left outer join fetch obj.groupExperimenterMap as map left outer join fetch map.child e where obj.id in (:ids), PARAMS:ids=ArrayList(1) ]
2014-08-12 11:46:54,571 INFO  [    ome.security.basic.BasicEventContext] (Server-637)  cctx:   group=-1
2014-08-12 11:46:54,577 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=-1,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,584 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840414569] time[14] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2014-08-12 11:46:54,584 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   ome.model.meta.ExperimenterGroup:Id_53
2014-08-12 11:46:54,595 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IQuery.findAllByQuery
2014-08-12 11:46:54,595 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [select e from ExperimenterGroup as e where e.id in (:ids), PARAMS:ids=ArrayList(4) ]
2014-08-12 11:46:54,597 INFO  [    ome.security.basic.BasicEventContext] (Server-639)  cctx:   group=-1
2014-08-12 11:46:54,603 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=2,group=-1,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,608 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840414596] time[12] tag[omero.call.success.ome.logic.QueryImpl.findAllByQuery]
2014-08-12 11:46:54,608 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   (ome.model.meta.ExperimenterGroup:Id_0, ome.model.meta.ExperimenterGroup:Id_1, ome.model.meta.ExperimenterGroup:Id_53, ... 1 more)
2014-08-12 11:46:54,614 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IQuery.findAllByQuery
2014-08-12 11:46:54,615 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [select distinct obj from ExperimenterGroup as obj left outer join fetch obj.groupExperimenterMap as map left outer join fetch map.child e, PARAMS]
2014-08-12 11:46:54,616 INFO  [    ome.security.basic.BasicEventContext] (Server-637)  cctx:   group=-1
2014-08-12 11:46:54,621 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=-1,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,637 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840414615] time[21] tag[omero.call.success.ome.logic.QueryImpl.findAllByQuery]
2014-08-12 11:46:54,637 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   (ome.model.meta.ExperimenterGroup:Id_1, ome.model.meta.ExperimenterGroup:Id_54, ome.model.meta.ExperimenterGroup:Id_53, ... 4 more)
2014-08-12 11:46:54,659 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IQuery.findByQuery
2014-08-12 11:46:54,660 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [select distinct obj from ExperimenterGroup as obj left outer join fetch obj.groupExperimenterMap as map left outer join fetch map.child e where obj.id in (:ids), PARAMS:ids=ArrayList(1) ]
2014-08-12 11:46:54,661 INFO  [    ome.security.basic.BasicEventContext] (Server-639)  cctx:   group=-1
2014-08-12 11:46:54,667 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=2,group=-1,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,677 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840414660] time[16] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2014-08-12 11:46:54,677 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   ome.model.meta.ExperimenterGroup:Id_54
2014-08-12 11:46:54,683 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IQuery.findByQuery
2014-08-12 11:46:54,684 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [select distinct obj from ExperimenterGroup as obj left outer join fetch obj.groupExperimenterMap as map left outer join fetch map.child e where obj.id in (:ids), PARAMS:ids=ArrayList(1) ]
2014-08-12 11:46:54,686 INFO  [    ome.security.basic.BasicEventContext] (Server-637)  cctx:   group=-1
2014-08-12 11:46:54,692 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=-1,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,700 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840414684] time[15] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2014-08-12 11:46:54,700 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   ome.model.meta.ExperimenterGroup:Id_103
2014-08-12 11:46:54,705 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IQuery.findByQuery
2014-08-12 11:46:54,705 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [select distinct obj from ExperimenterGroup as obj left outer join fetch obj.groupExperimenterMap as map left outer join fetch map.child e where obj.id in (:ids), PARAMS:ids=ArrayList(1) ]
2014-08-12 11:46:54,706 INFO  [    ome.security.basic.BasicEventContext] (Server-639)  cctx:   group=-1
2014-08-12 11:46:54,710 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=2,group=-1,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,716 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840414705] time[11] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2014-08-12 11:46:54,717 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   ome.model.meta.ExperimenterGroup:Id_3
2014-08-12 11:46:54,721 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IQuery.findByQuery
2014-08-12 11:46:54,722 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [select distinct obj from ExperimenterGroup as obj left outer join fetch obj.groupExperimenterMap as map left outer join fetch map.child e where obj.id in (:ids), PARAMS:ids=ArrayList(1) ]
2014-08-12 11:46:54,723 INFO  [    ome.security.basic.BasicEventContext] (Server-637)  cctx:   group=-1
2014-08-12 11:46:54,727 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=-1,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,731 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840414722] time[9] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2014-08-12 11:46:54,732 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   ome.model.meta.ExperimenterGroup:Id_53
2014-08-12 11:46:54,737 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IQuery.findByQuery
2014-08-12 11:46:54,737 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [select distinct obj from ExperimenterGroup as obj left outer join fetch obj.groupExperimenterMap as map left outer join fetch map.child e where obj.id in (:ids), PARAMS:ids=ArrayList(1) ]
2014-08-12 11:46:54,738 INFO  [    ome.security.basic.BasicEventContext] (Server-639)  cctx:   group=-1
2014-08-12 11:46:54,743 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=2,group=-1,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,749 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840414738] time[11] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2014-08-12 11:46:54,750 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   ome.model.meta.ExperimenterGroup:Id_0
2014-08-12 11:46:54,753 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IQuery.findByQuery
2014-08-12 11:46:54,754 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [select distinct obj from ExperimenterGroup as obj left outer join fetch obj.groupExperimenterMap as map left outer join fetch map.child e where obj.id in (:ids), PARAMS:ids=ArrayList(1) ]
2014-08-12 11:46:54,755 INFO  [    ome.security.basic.BasicEventContext] (Server-637)  cctx:   group=-1
2014-08-12 11:46:54,760 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=-1,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,764 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840414754] time[10] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2014-08-12 11:46:54,764 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   ome.model.meta.ExperimenterGroup:Id_53
2014-08-12 11:46:54,772 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IQuery.findByQuery
2014-08-12 11:46:54,772 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [select distinct obj from Experimenter as obj left outer join fetch obj.groupExperimenterMap as map left outer join fetch map.parent g where obj.id in (:ids), PARAMS:ids=ArrayList(1) ]
2014-08-12 11:46:54,773 INFO  [    ome.security.basic.BasicEventContext] (Server-639)  cctx:   group=-1
2014-08-12 11:46:54,776 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=2,group=-1,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,785 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840414772] time[12] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2014-08-12 11:46:54,785 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   ome.model.meta.Experimenter:Id_2
2014-08-12 11:46:54,832 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IQuery.findByQuery
2014-08-12 11:46:54,832 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [select distinct obj from Experimenter as obj left outer join fetch obj.groupExperimenterMap as map left outer join fetch map.parent g where obj.id in (:ids), PARAMS:ids=ArrayList(1) ]
2014-08-12 11:46:54,832 INFO  [    ome.security.basic.BasicEventContext] (Server-637)  cctx:   group=-1
2014-08-12 11:46:54,835 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=-1,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:54,844 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840414832] time[11] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2014-08-12 11:46:54,844 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   ome.model.meta.Experimenter:Id_2
2014-08-12 11:46:54,887 INFO  [o.services.sessions.SessionContext$Count] (Server-639) -Reference count: 6372e1fd-0d82-4073-b28e-8636348b1a49=1
2014-08-12 11:46:54,887 INFO  [                      omero.cmd.SessionI] (Server-639) cleanupSelf(ServiceFactoryI(session-95257f73-f80d-4ad7-8ef5-3e712bb5a763/6372e1fd-0d82-4073-b28e-8636348b1a49)).
2014-08-12 11:46:54,887 INFO  [                      omero.cmd.SessionI] (Server-639) Unregistered servant:6372e1fd-0d82-4073-b28e-8636348b1a49/95257f73-f80d-4ad7-8ef5-3e712bb5a763omero.api.IAdmin(omero.api._IAdminTie@136141f4)
2014-08-12 11:46:54,887 INFO  [                      omero.cmd.SessionI] (Server-639) Removed servant from adapter: 95257f73-f80d-4ad7-8ef5-3e712bb5a763omero.api.IAdmin
2014-08-12 11:46:54,887 INFO  [                      omero.cmd.SessionI] (Server-639) Unregistered servant:6372e1fd-0d82-4073-b28e-8636348b1a49/95257f73-f80d-4ad7-8ef5-3e712bb5a763omero.api.IQuery(omero.api._IQueryTie@815a32c7)
2014-08-12 11:46:54,887 INFO  [                      omero.cmd.SessionI] (Server-639) Removed servant from adapter: 95257f73-f80d-4ad7-8ef5-3e712bb5a763omero.api.IQuery
2014-08-12 11:46:55,012 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-639) Found session locally: 6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,014 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-639) Rejoining session ServiceFactoryI(session-9d8971bc-759c-4e21-9902-a0de587695bd/6372e1fd-0d82-4073-b28e-8636348b1a49) (agent=OMERO.web)
2014-08-12 11:46:55,024 INFO  [                      omero.cmd.SessionI] (Server-637) Added servant to adapter: 6372e1fd-0d82-4073-b28e-8636348b1a49/9d8971bc-759c-4e21-9902-a0de587695bdomero.api.IMetadata(omero.api._IMetadataTie@67e94767)
2014-08-12 11:46:55,029 INFO  [                      omero.cmd.SessionI] (Server-639) Added servant to adapter: 6372e1fd-0d82-4073-b28e-8636348b1a49/9d8971bc-759c-4e21-9902-a0de587695bdomero.api.IAdmin(omero.api._IAdminTie@40e47cb4)
2014-08-12 11:46:55,032 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IAdmin.getEventContext
2014-08-12 11:46:55,032 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   ()
2014-08-12 11:46:55,036 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,036 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(6372e1fd-0d82-4073-b28e-8636348b1a49)
2014-08-12 11:46:55,037 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:55,039 INFO  [         ome.security.basic.EventHandler] (3-thread-8)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:55,050 INFO  [                 org.perf4j.TimingLogger] (3-thread-8) start[1407840415037] time[13] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2014-08-12 11:46:55,050 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Rslt:   (ome.model.meta.Experimenter:Id_2, ome.model.meta.ExperimenterGroup:Id_53, (53, 1, 0, ... 1 more), ... 4 more)
2014-08-12 11:46:55,052 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840415032] time[19] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2014-08-12 11:46:55,052 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   ome.system.SimpleEventContext@62bdc816
2014-08-12 11:46:55,055 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IMetadata.loadAnnotations
2014-08-12 11:46:55,056 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [class ome.model.meta.Experimenter, (2), (), (), null]
2014-08-12 11:46:55,058 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,071 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840415056] time[14] tag[omero.call.success.ome.logic.MetadataImpl.loadAnnotations]
2014-08-12 11:46:55,071 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   {2=()}
2014-08-12 11:46:55,087 INFO  [o.services.sessions.SessionContext$Count] (Server-637) -Reference count: 6372e1fd-0d82-4073-b28e-8636348b1a49=1
2014-08-12 11:46:55,087 INFO  [                      omero.cmd.SessionI] (Server-637) cleanupSelf(ServiceFactoryI(session-9d8971bc-759c-4e21-9902-a0de587695bd/6372e1fd-0d82-4073-b28e-8636348b1a49)).
2014-08-12 11:46:55,088 INFO  [                      omero.cmd.SessionI] (Server-637) Unregistered servant:6372e1fd-0d82-4073-b28e-8636348b1a49/9d8971bc-759c-4e21-9902-a0de587695bdomero.api.IAdmin(omero.api._IAdminTie@40e47cb4)
2014-08-12 11:46:55,088 INFO  [                      omero.cmd.SessionI] (Server-637) Removed servant from adapter: 9d8971bc-759c-4e21-9902-a0de587695bdomero.api.IAdmin
2014-08-12 11:46:55,088 INFO  [                      omero.cmd.SessionI] (Server-637) Unregistered servant:6372e1fd-0d82-4073-b28e-8636348b1a49/9d8971bc-759c-4e21-9902-a0de587695bdomero.api.IMetadata(omero.api._IMetadataTie@67e94767)
2014-08-12 11:46:55,088 INFO  [                      omero.cmd.SessionI] (Server-637) Removed servant from adapter: 9d8971bc-759c-4e21-9902-a0de587695bdomero.api.IMetadata
2014-08-12 11:46:55,448 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-637) Found session locally: 6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,452 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-637) Rejoining session ServiceFactoryI(session-7ed3eddc-173d-4f9b-96d3-afe074e7d51e/6372e1fd-0d82-4073-b28e-8636348b1a49) (agent=OMERO.web)
2014-08-12 11:46:55,457 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-637) Found session locally: 6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,459 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-637) Rejoining session ServiceFactoryI(session-20c5459b-8400-479b-a231-7ddd749a314d/6372e1fd-0d82-4073-b28e-8636348b1a49) (agent=OMERO.web)
2014-08-12 11:46:55,460 INFO  [                      omero.cmd.SessionI] (Server-639) Added servant to adapter: 6372e1fd-0d82-4073-b28e-8636348b1a49/7ed3eddc-173d-4f9b-96d3-afe074e7d51eomero.api.IAdmin(omero.api._IAdminTie@34488d4e)
2014-08-12 11:46:55,462 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Meth:   interface ome.api.IAdmin.getEventContext
2014-08-12 11:46:55,462 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Args:   ()
2014-08-12 11:46:55,465 INFO  [         ome.security.basic.EventHandler] (Server-641)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,466 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(6372e1fd-0d82-4073-b28e-8636348b1a49)
2014-08-12 11:46:55,466 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:55,470 INFO  [         ome.security.basic.EventHandler] (3-thread-8)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:55,470 INFO  [                      omero.cmd.SessionI] (Server-637) Added servant to adapter: 6372e1fd-0d82-4073-b28e-8636348b1a49/20c5459b-8400-479b-a231-7ddd749a314domero.api.IAdmin(omero.api._IAdminTie@83e1d735)
2014-08-12 11:46:55,472 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IAdmin.getEventContext
2014-08-12 11:46:55,472 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   ()
2014-08-12 11:46:55,480 INFO  [                 org.perf4j.TimingLogger] (3-thread-8) start[1407840415466] time[13] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2014-08-12 11:46:55,481 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Rslt:   (ome.model.meta.Experimenter:Id_2, ome.model.meta.ExperimenterGroup:Id_53, (53, 1, 0, ... 1 more), ... 4 more)
2014-08-12 11:46:55,482 INFO  [                 org.perf4j.TimingLogger] (Server-641) start[1407840415462] time[19] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2014-08-12 11:46:55,483 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Rslt:   ome.system.SimpleEventContext@7bc7413
2014-08-12 11:46:55,483 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,484 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(6372e1fd-0d82-4073-b28e-8636348b1a49)
2014-08-12 11:46:55,484 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:55,487 INFO  [         ome.security.basic.EventHandler] (3-thread-8)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:55,495 INFO  [                 org.perf4j.TimingLogger] (3-thread-8) start[1407840415484] time[10] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2014-08-12 11:46:55,495 INFO  [        ome.services.util.ServiceHandler] (3-thread-8)  Rslt:   (ome.model.meta.Experimenter:Id_2, ome.model.meta.ExperimenterGroup:Id_53, (53, 1, 0, ... 1 more), ... 4 more)
2014-08-12 11:46:55,496 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840415472] time[23] tag[omero.call.success.ome.logic.AdminImpl.getEventContext]
2014-08-12 11:46:55,496 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   ome.system.SimpleEventContext@6d13280c
2014-08-12 11:46:55,498 INFO  [o.services.sessions.SessionContext$Count] (Server-641) -Reference count: 6372e1fd-0d82-4073-b28e-8636348b1a49=2
2014-08-12 11:46:55,498 INFO  [                      omero.cmd.SessionI] (Server-641) cleanupSelf(ServiceFactoryI(session-7ed3eddc-173d-4f9b-96d3-afe074e7d51e/6372e1fd-0d82-4073-b28e-8636348b1a49)).
2014-08-12 11:46:55,498 INFO  [                      omero.cmd.SessionI] (Server-641) Unregistered servant:6372e1fd-0d82-4073-b28e-8636348b1a49/7ed3eddc-173d-4f9b-96d3-afe074e7d51eomero.api.IAdmin(omero.api._IAdminTie@34488d4e)
2014-08-12 11:46:55,498 INFO  [                      omero.cmd.SessionI] (Server-641) Removed servant from adapter: 7ed3eddc-173d-4f9b-96d3-afe074e7d51eomero.api.IAdmin
2014-08-12 11:46:55,498 INFO  [                      omero.cmd.SessionI] (Server-637) Added servant to adapter: 6372e1fd-0d82-4073-b28e-8636348b1a49/20c5459b-8400-479b-a231-7ddd749a314domero.api.IQuery(omero.api._IQueryTie@3cf83775)
2014-08-12 11:46:55,500 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IQuery.findByQuery
2014-08-12 11:46:55,500 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [select distinct obj from Experimenter as obj left outer join fetch obj.groupExperimenterMap as map left outer join fetch map.parent g where obj.id in (:ids), PARAMS:ids=ArrayList(1) ]
2014-08-12 11:46:55,502 INFO  [    ome.security.basic.BasicEventContext] (Server-639)  cctx:   group=53
2014-08-12 11:46:55,502 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,506 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840415500] time[5] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2014-08-12 11:46:55,506 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   ome.model.meta.Experimenter:Id_2
2014-08-12 11:46:55,513 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Meth:   interface ome.api.IQuery.projection
2014-08-12 11:46:55,513 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Args:   [
        select project.id,
               project.name,
               project.details.owner.id,
               project.details.group.id,
               project.details.permissions,
               dataset.id,
               dataset.name,
               dataset.details.owner.id,
               dataset.details.group.id,
               dataset.details.permissions,
               (select count(id) from DatasetImageLink dil
                  where dil.parent = dataset.id)
               from Project as project
               left join project.datasetLinks as pdlink
               left join pdlink.child dataset
        where project.details.owner.id = :id
        order by lower(project.name), lower(dataset.name)
        , PARAMS:id=2 ]
2014-08-12 11:46:55,515 INFO  [    ome.security.basic.BasicEventContext] (Server-641)  cctx:   group=53
2014-08-12 11:46:55,516 INFO  [         ome.security.basic.EventHandler] (Server-641)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,523 INFO  [                 org.perf4j.TimingLogger] (Server-641) start[1407840415513] time[10] tag[omero.call.success.ome.logic.QueryImpl.projection]
2014-08-12 11:46:55,523 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Rslt:   ([151, SOFI-tubulin, 2, ... 1 more], [151, SOFI-tubulin, 2, ... 1 more])
2014-08-12 11:46:55,527 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IQuery.projection
2014-08-12 11:46:55,527 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [
            select obj from Project obj where obj.id = :id
            , PARAMS:id=151 ]
2014-08-12 11:46:55,530 INFO  [    ome.security.basic.BasicEventContext] (Server-637)  cctx:   group=53
2014-08-12 11:46:55,531 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,534 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840415528] time[6] tag[omero.call.success.ome.logic.QueryImpl.projection]
2014-08-12 11:46:55,534 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   ([ome.model.containers.Project:Id_151])
2014-08-12 11:46:55,536 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IQuery.projection
2014-08-12 11:46:55,536 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [
        select dataset.id,
               dataset.name,
               dataset.details.owner.id,
               dataset.details.group.id,
               dataset.details.permissions,
               (select count(id) from DatasetImageLink dil
                 where dil.parent=dataset.id)
               from Dataset dataset
        where not exists (
            select pdlink from ProjectDatasetLink as pdlink
            where pdlink.child = dataset.id
        ) and dataset.details.owner.id = :id
        order by lower(dataset.name)
        , PARAMS:id=2 ]
2014-08-12 11:46:55,538 INFO  [    ome.security.basic.BasicEventContext] (Server-639)  cctx:   group=53
2014-08-12 11:46:55,538 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,543 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840415536] time[6] tag[omero.call.success.ome.logic.QueryImpl.projection]
2014-08-12 11:46:55,543 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   ()
2014-08-12 11:46:55,544 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Meth:   interface ome.api.IQuery.projection
2014-08-12 11:46:55,544 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Args:   [
        select screen.id,
               screen.name,
               screen.details.owner.id,
               screen.details.group.id,
               screen.details.permissions,
               plate.id,
               plate.name,
               plate.details.owner.id,
               plate.details.group.id,
               plate.details.permissions,
               pa.id,
               pa.name,
               pa.details.owner.id,
               pa.details.group.id,
               pa.details.permissions,
               pa.startTime,
               pa.endTime
               from Screen screen
               left join screen.plateLinks splink
               left join splink.child plate
               left join plate.plateAcquisitions pa
        where screen.details.owner.id = :id
        order by lower(screen.name), lower(plate.name), pa.id
        , PARAMS:id=2 ]
2014-08-12 11:46:55,546 INFO  [    ome.security.basic.BasicEventContext] (Server-641)  cctx:   group=53
2014-08-12 11:46:55,546 INFO  [         ome.security.basic.EventHandler] (Server-641)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,554 INFO  [                 org.perf4j.TimingLogger] (Server-641) start[1407840415544] time[9] tag[omero.call.success.ome.logic.QueryImpl.projection]
2014-08-12 11:46:55,554 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Rslt:   ()
2014-08-12 11:46:55,555 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.IQuery.projection
2014-08-12 11:46:55,555 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [
        select plate.id,
               plate.name,
               plate.details.owner.id,
               plate.details.group.id,
               plate.details.permissions,
               pa.id,
               pa.name,
               pa.details.owner.id,
               pa.details.group.id,
               pa.details.permissions,
               pa.startTime,
               pa.endTime
               from Plate plate
               left join plate.plateAcquisitions pa
        where not exists (
            select splink from ScreenPlateLink as splink
            where splink.child = plate.id
        ) and plate.details.owner.id = :id
        order by lower(plate.name), pa.id
        , PARAMS:id=2 ]
2014-08-12 11:46:55,557 INFO  [    ome.security.basic.BasicEventContext] (Server-637)  cctx:   group=53
2014-08-12 11:46:55,557 INFO  [         ome.security.basic.EventHandler] (Server-637)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,560 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840415555] time[4] tag[omero.call.success.ome.logic.QueryImpl.projection]
2014-08-12 11:46:55,560 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   ()
2014-08-12 11:46:55,562 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Meth:   interface ome.api.IQuery.projection
2014-08-12 11:46:55,562 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Args:   [select count(obj.id) from Image as obj join obj.details.creationEvent join obj.details.owner join obj.details.group where obj.details.owner.id=:eid and not exists (select obl from DatasetImageLink as obl where obl.child=obj.id)and not exists ( select ws from WellSample as ws where ws.image=obj.id  and ws.details.owner.id=:eid), PARAMS:eid=2 ]
2014-08-12 11:46:55,564 INFO  [    ome.security.basic.BasicEventContext] (Server-639)  cctx:   group=53
2014-08-12 11:46:55,564 INFO  [         ome.security.basic.EventHandler] (Server-639)  Auth:   user=2,group=53,event=null(User),sess=6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:55,578 INFO  [                 org.perf4j.TimingLogger] (Server-639) start[1407840415562] time[15] tag[omero.call.success.ome.logic.QueryImpl.projection]
2014-08-12 11:46:55,578 INFO  [        ome.services.util.ServiceHandler] (Server-639)  Rslt:   ([0])
2014-08-12 11:46:55,593 INFO  [o.services.sessions.SessionContext$Count] (Server-641) -Reference count: 6372e1fd-0d82-4073-b28e-8636348b1a49=1
2014-08-12 11:46:55,593 INFO  [                      omero.cmd.SessionI] (Server-641) cleanupSelf(ServiceFactoryI(session-20c5459b-8400-479b-a231-7ddd749a314d/6372e1fd-0d82-4073-b28e-8636348b1a49)).
2014-08-12 11:46:55,593 INFO  [                      omero.cmd.SessionI] (Server-641) Unregistered servant:6372e1fd-0d82-4073-b28e-8636348b1a49/20c5459b-8400-479b-a231-7ddd749a314domero.api.IQuery(omero.api._IQueryTie@3cf83775)
2014-08-12 11:46:55,593 INFO  [                      omero.cmd.SessionI] (Server-641) Removed servant from adapter: 20c5459b-8400-479b-a231-7ddd749a314domero.api.IQuery
2014-08-12 11:46:55,593 INFO  [                      omero.cmd.SessionI] (Server-641) Unregistered servant:6372e1fd-0d82-4073-b28e-8636348b1a49/20c5459b-8400-479b-a231-7ddd749a314domero.api.IAdmin(omero.api._IAdminTie@83e1d735)
2014-08-12 11:46:55,593 INFO  [                      omero.cmd.SessionI] (Server-641) Removed servant from adapter: 20c5459b-8400-479b-a231-7ddd749a314domero.api.IAdmin
2014-08-12 11:46:59,327 INFO  [ome.services.sessions.state.SessionCache] (2-thread-4) Synchronizing session cache. Count = 6
2014-08-12 11:46:59,327 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(d0a5e210-29da-441a-87e4-b182f5fa7911)
2014-08-12 11:46:59,327 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:59,330 INFO  [         ome.security.basic.EventHandler] (2-thread-4)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:59,339 INFO  [                 org.perf4j.TimingLogger] (2-thread-4) start[1407840419327] time[11] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2014-08-12 11:46:59,339 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Rslt:   (ome.model.meta.Experimenter:Id_1, ome.model.meta.ExperimenterGroup:Id_2, (2), ... 4 more)
2014-08-12 11:46:59,339 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(6372e1fd-0d82-4073-b28e-8636348b1a49)
2014-08-12 11:46:59,339 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:59,340 INFO  [         ome.security.basic.EventHandler] (2-thread-4)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:59,347 INFO  [                 org.perf4j.TimingLogger] (2-thread-4) start[1407840419339] time[7] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2014-08-12 11:46:59,347 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Rslt:   (ome.model.meta.Experimenter:Id_2, ome.model.meta.ExperimenterGroup:Id_53, (53, 1, 0, ... 1 more), ... 4 more)
2014-08-12 11:46:59,347 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(ac85630f-844d-4997-a7f6-180161df34e1)
2014-08-12 11:46:59,347 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:59,349 INFO  [         ome.security.basic.EventHandler] (2-thread-4)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:59,356 INFO  [                 org.perf4j.TimingLogger] (2-thread-4) start[1407840419347] time[8] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2014-08-12 11:46:59,356 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Rslt:   (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2014-08-12 11:46:59,357 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(9b231fee-cc81-4969-bf3b-3bcc00325f6d)
2014-08-12 11:46:59,357 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:59,358 INFO  [         ome.security.basic.EventHandler] (2-thread-4)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:59,365 INFO  [                 org.perf4j.TimingLogger] (2-thread-4) start[1407840419357] time[8] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2014-08-12 11:46:59,365 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Rslt:   (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2014-08-12 11:46:59,365 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(a15fde1e-56b8-485a-9cb1-d36abb0ddcb5)
2014-08-12 11:46:59,365 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:59,369 INFO  [         ome.security.basic.EventHandler] (2-thread-4)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:59,380 INFO  [                 org.perf4j.TimingLogger] (2-thread-4) start[1407840419366] time[14] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2014-08-12 11:46:59,380 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Rslt:   (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2014-08-12 11:46:59,380 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(22ee5c5f-3863-485d-9fe3-d8107c5eae23)
2014-08-12 11:46:59,381 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Args:   [null, InternalSF@1606488103]
2014-08-12 11:46:59,381 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-639) Found session locally: 6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:59,383 INFO  [ ome.services.blitz.fire.SessionManagerI] (Server-639) Rejoining session ServiceFactoryI(session-45c9944f-2ba3-43f4-a605-6b79ffe568d0/6372e1fd-0d82-4073-b28e-8636348b1a49) (agent=OMERO.web)
2014-08-12 11:46:59,383 INFO  [         ome.security.basic.EventHandler] (2-thread-4)  Auth:   user=0,group=0,event=null(Sessions),sess=9b231fee-cc81-4969-bf3b-3bcc00325f6d
2014-08-12 11:46:59,388 INFO  [                 org.perf4j.TimingLogger] (2-thread-4) start[1407840419381] time[7] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2014-08-12 11:46:59,388 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Rslt:   (ome.model.meta.Experimenter:Id_1, ome.model.meta.ExperimenterGroup:Id_2, (2), ... 4 more)
2014-08-12 11:46:59,388 INFO  [                 org.perf4j.TimingLogger] (2-thread-4) start[1407840419327] time[61] tag[omero.sessions.synchronization]
2014-08-12 11:46:59,389 INFO  [ome.services.sessions.state.SessionCache] (2-thread-4) Synchronization took 61 ms.
2014-08-12 11:46:59,390 INFO  [                      omero.cmd.SessionI] (Server-639) Added servant to adapter: 6372e1fd-0d82-4073-b28e-8636348b1a49/45c9944f-2ba3-43f4-a605-6b79ffe568d0omero.api.ISession(omero.api._ISessionTie@39e93e97)
2014-08-12 11:46:59,393 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Meth:   interface ome.api.ISession.closeSession
2014-08-12 11:46:59,393 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Args:   [ome.model.meta.Session:Hash_1600559101]
2014-08-12 11:46:59,393 INFO  [o.services.sessions.SessionContext$Count] (2-thread-3) -Reference count: 6372e1fd-0d82-4073-b28e-8636348b1a49=1
2014-08-12 11:46:59,393 INFO  [ome.services.sessions.SessionManagerImpl] (2-thread-3) closeSession called but 1 more references: 6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:59,394 INFO  [                 org.perf4j.TimingLogger] (Server-641) start[1407840419393] time[0] tag[omero.call.success.ome.services.sessions.SessionBean.closeSession]
2014-08-12 11:46:59,394 INFO  [        ome.services.util.ServiceHandler] (Server-641)  Rslt:   1
2014-08-12 11:46:59,396 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Meth:   interface ome.api.ISession.closeSession
2014-08-12 11:46:59,396 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Args:   [ome.model.meta.Session:Hash_1191155780]
2014-08-12 11:46:59,396 INFO  [o.services.sessions.SessionContext$Count] (2-thread-2) -Reference count: 6372e1fd-0d82-4073-b28e-8636348b1a49=0
2014-08-12 11:46:59,396 INFO  [ome.services.sessions.SessionManagerImpl] (2-thread-2) closeSession called and no more references: 6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:59,396 INFO  [ome.services.sessions.state.SessionCache] (2-thread-2) Destroying session 6372e1fd-0d82-4073-b28e-8636348b1a49 due to : Remove session called
2014-08-12 11:46:59,396 INFO  [                 org.perf4j.TimingLogger] (2-thread-2) start[1407840413120] time[6276] tag[omero.session]
2014-08-12 11:46:59,398 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-2) Reaping 2 clients for 6372e1fd-0d82-4073-b28e-8636348b1a49
2014-08-12 11:46:59,399 INFO  [                      omero.cmd.SessionI] (2-thread-2) doDestroy(ServiceFactoryI(session-45c9944f-2ba3-43f4-a605-6b79ffe568d0/6372e1fd-0d82-4073-b28e-8636348b1a49))
2014-08-12 11:46:59,399 INFO  [                      omero.cmd.SessionI] (2-thread-2) Unregistered servant:6372e1fd-0d82-4073-b28e-8636348b1a49/45c9944f-2ba3-43f4-a605-6b79ffe568d0omero.api.ISession(omero.api._ISessionTie@39e93e97)
2014-08-12 11:46:59,399 INFO  [                      omero.cmd.SessionI] (2-thread-2) Removed servant from adapter: 45c9944f-2ba3-43f4-a605-6b79ffe568d0omero.api.ISession
2014-08-12 11:46:59,399 INFO  [                      omero.cmd.SessionI] (2-thread-2) Unregistered servant:6372e1fd-0d82-4073-b28e-8636348b1a49/5dfc7fbf-ffae-4e6f-8e03-acbf889f7a93omero.api.IAdmin(omero.api._IAdminTie@85dfcbec)
2014-08-12 11:46:59,399 INFO  [                      omero.cmd.SessionI] (2-thread-2) Removed servant from adapter: 5dfc7fbf-ffae-4e6f-8e03-acbf889f7a93omero.api.IAdmin
2014-08-12 11:46:59,399 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-2) Removing ServiceFactoryI(session-45c9944f-2ba3-43f4-a605-6b79ffe568d0/6372e1fd-0d82-4073-b28e-8636348b1a49)
2014-08-12 11:46:59,399 INFO  [                      omero.cmd.SessionI] (2-thread-2) doDestroy(ServiceFactoryI(session-5dfc7fbf-ffae-4e6f-8e03-acbf889f7a93/6372e1fd-0d82-4073-b28e-8636348b1a49))
2014-08-12 11:46:59,399 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-2) Removing ServiceFactoryI(session-5dfc7fbf-ffae-4e6f-8e03-acbf889f7a93/6372e1fd-0d82-4073-b28e-8636348b1a49)
2014-08-12 11:46:59,400 INFO  [                 org.perf4j.TimingLogger] (Server-637) start[1407840419396] time[4] tag[omero.call.success.ome.services.sessions.SessionBean.closeSession]
2014-08-12 11:46:59,400 INFO  [        ome.services.util.ServiceHandler] (Server-637)  Rslt:   -2



[davemason]

One more piece of the puzzle, I was originally looking at the $USERHOME\omero\log\omeroinsight.log, but I've just noticed a log in the insight program directory called error.log, which updates every time I try to login with insight:

Code: Select all

!! 12/08/14 13:07:52:679 error: Ice.ThreadPool.Client-0: exception in `Ice.ThreadPool.Client':
   java.lang.RuntimeException: Algorithm NONE not available
      at sun.security.ssl.Handshaker.checkThrown(Unknown Source)
      at sun.security.ssl.SSLEngineImpl.checkTaskThrown(Unknown Source)
      at sun.security.ssl.SSLEngineImpl.readNetRecord(Unknown Source)
      at sun.security.ssl.SSLEngineImpl.unwrap(Unknown Source)
      at javax.net.ssl.SSLEngine.unwrap(Unknown Source)
      at IceSSL.TransceiverI.handshakeNonBlocking(TransceiverI.java:543)
      at IceSSL.TransceiverI.initialize(TransceiverI.java:109)
      at Ice.ConnectionI.initialize(ConnectionI.java:1933)
      at Ice.ConnectionI.message(ConnectionI.java:1084)
      at IceInternal.ThreadPool.run(ThreadPool.java:321)
      at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
      at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:693)
      at java.lang.Thread.run(Unknown Source)
   Caused by: java.lang.RuntimeException: Algorithm NONE not available
      at sun.security.ssl.JsseJce.getMessageDigest(Unknown Source)
      at sun.security.ssl.CloneableDigest.getDigest(Unknown Source)
      at sun.security.ssl.HandshakeHash.setFinishedAlg(Unknown Source)
      at sun.security.ssl.ClientHandshaker.serverHello(Unknown Source)
      at sun.security.ssl.ClientHandshaker.processMessage(Unknown Source)
      at sun.security.ssl.Handshaker.processLoop(Unknown Source)
      at sun.security.ssl.Handshaker$1.run(Unknown Source)
      at sun.security.ssl.Handshaker$1.run(Unknown Source)
      at java.security.AccessController.doPrivileged(Native Method)
      at sun.security.ssl.Handshaker$DelegatedTask.run(Unknown Source)
      at IceSSL.TransceiverI.handshakeNonBlocking(TransceiverI.java:530)
      ... 7 more
   Caused by: java.security.NoSuchAlgorithmException: NONE MessageDigest not available
      at sun.security.jca.GetInstance.getInstance(Unknown Source)
      at java.security.Security.getImpl(Unknown Source)
      at java.security.MessageDigest.getInstance(Unknown Source)
      ... 18 more
   
   event handler: local address = <not available>
   remote address = 138.253.100.97:4064


[manics]

Hi Dave

Are you running Java 8 on the client? Unfortunately there's a bug in OMERO which we weren't able to fix in time for the 5.0.3 release, though we think we've identified and fixed the problem in the past few days so it should be in 5.0.4.

If this is the problem then I'm afraid the only current workaround is use Java 7. We should have an internal test build available soon (hopefully within a week or two) which isn't recommended for production use, but if you want you could try it out to see if it fixes the problem (and if it doesn't that's definitely useful for us to know).

If that isn't the problem could you paste the output of

Code: Select all

java -version

on the server and client?

Thanks, Simon

[davemason]

Nailed it.

Server side is 1.6.0 but client side I had updated to 1.8. After uninstalling that it works as expected. All I have to do now is check my other users' Java versions. Sorry for not reporting the right log in the first place!

A big thank you for stopping me banging my head against a wall for the rest of the week!

Dave

[manics]

Hi Dave

Thanks for letting us know.

Simon