VM omero having postrgres problems

[Thorondor]

I installed the VM from http://www.openmicroscopy.org/site/supp ... _appliance

and get some problems with postrges:

Code: Select all

Parsing Blitz-0.log:[line:113] => Server restarted <= Parsing Blitz-0.log:
[line:230] Your postgres hostname and/or port is invalid Parsing Blitz-0.log:
[line:336] Your postgres hostname and/or port is invalid Parsing Blitz-0.log:
[line:416] Your postgres hostname and/or port is invalid Parsing Blitz-0.log:
[line:574] Your postgres hostname and/or port is invalid Parsing Blitz-0.log:
[line:810] => Server restarted <= Parsing Blitz-0.log:[line:1022] => Server restarted <= Parsing Blitz-0.log:[line:10842] Your postgres hostname and/or port is invalid Parsing Blitz-0.log:[line:11078] => Server restarted <= Parsing Blitz-0.log:[line:11482] => Server restarted <= Parsing Blitz-0.log:[line:11901] Your postgres hostname and/or port is invalid Parsing Blitz-0.log:[line:12075] Your postgres hostname and/or port is invalid Parsing Blitz-0.log:[line:12311] => Server restarted <= Environment:OMERO_HOME=(unset) Environment:OMERO_NODE=(unset) Environment:OMERO_MASTER=(unset) Environment:PATH=/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games:/usr/lib/jvm/java-6-sun/bin:/usr/lib/jvm/java-6-sun/bin:/usr/share/Ice-3.3.1:/usr/lib/postgresql/8.4/bin:/home/omero/OMERO.server/bin Environment:ICE_HOME=/usr/share/Ice-3.3.1 Environment:LD_LIBRARY_PATH=/usr/share/java:/usr/lib: Environment:DYLD_LIBRARY_PATH=/usr/share/java:/usr/lib: OMERO data dir: '/home/omero/OMERO.data' Exists? True Is writable? True OMERO.web status... [NOT STARTED]


Do I have to set something for postrgres? Anything that I might have missed?

[jmoore]

Which URL did you use to download the .ova and can you send us the entire Blitz log?
~J

[Thorondor]

vm download file:
http://hudson.openmicroscopy.org.uk/job ... ero-vm.ova

blitz log is too large for one post, so I split it:

Code: Select all

2012-05-03 15:12:50,085 INFO  [                ome.services.blitz.Entry] (      main) Creating OMERO.blitz. Please wait...
2012-05-03 15:12:55,477 INFO  [ng.ShutdownSafeEhcacheManagerFactoryBean] (      main) Initializing EHCache CacheManager
2012-05-03 15:12:57,555 INFO  [          ome.services.util.DBPatchCheck] (      main) Verified database patch: OMERO4.3__0
2012-05-03 15:13:06,936 INFO  [  ome.services.fulltext.FullTextAnalyzer] (      main) Initialized FullTextAnalyzer
2012-05-03 15:13:20,706 INFO  [        ome.services.db.DatabaseIdentity] (      main) Using LSID format: urn:lsid:export.openmicroscopy.org:%s:de968e1e-1f1c-411d-921b-48206f5ea301_%s%s
2012-05-03 15:13:22,269 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054400913] time[1356] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:22,776 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054402272] time[504] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:25,221 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054402779] time[2442] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:25,556 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054405221] time[335] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:25,960 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054405564] time[396] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:26,466 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054405965] time[501] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:27,084 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054406473] time[611] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:28,799 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054407091] time[1708] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:29,033 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054408800] time[233] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:29,279 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054409034] time[245] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:29,467 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054409285] time[182] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:29,590 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054409467] time[123] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:31,995 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054409590] time[2405] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:32,401 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054411995] time[406] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:32,670 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054412401] time[268] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:32,899 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054412670] time[229] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:33,135 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054412904] time[231] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:33,395 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054413140] time[255] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:33,735 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054413400] time[335] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:34,071 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054413741] time[330] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-03 15:13:34,107 INFO  [                ome.io.nio.PixelsService] (      main) PixelsService(path=/home/omero/OMERO.data, resolver=ome.services.OmeroFilePathResolver@1264c84, backoff=ome.io.nio.SimpleBackOff(factor=476.4), sizes=ome.io.nio.ConfiguredTileSizes(w=256,h=256,W=3192,H=3192))
2012-05-03 15:13:35,473 INFO  [    ome.services.fulltext.FullTextThread] (      main) Initializing Full-Text Indexer
2012-05-03 15:13:35,499 INFO  [  ome.services.pixeldata.PixelDataThread] (      main) Initializing PixelDataThread (create events only)
2012-05-03 15:13:36,663 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Zip
2012-05-03 15:13:36,669 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: APNG
2012-05-03 15:13:36,672 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: PCX
2012-05-03 15:13:36,677 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Ivision
2012-05-03 15:13:36,683 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: GatanDM2
2012-05-03 15:13:36,708 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: L2D
2012-05-03 15:13:36,709 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Companion/L2D
2012-05-03 15:13:36,710 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: FEI
2012-05-03 15:13:36,717 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: NAF
2012-05-03 15:13:36,718 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: MINC
2012-05-03 15:13:36,720 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: MRW
2012-05-03 15:13:36,721 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: TillVision
2012-05-03 15:13:36,722 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Companion/TillVision
2012-05-03 15:13:36,723 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: ARF
2012-05-03 15:13:36,725 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Cellomics
2012-05-03 15:13:36,726 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: LiFlim
2012-05-03 15:13:36,731 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Targa
2012-05-03 15:13:36,732 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: OxfordInstruments
2012-05-03 15:13:36,733 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: VGSAM
2012-05-03 15:13:36,734 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: HIS
2012-05-03 15:13:36,735 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: WATOP
2012-05-03 15:13:36,736 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Seiko
2012-05-03 15:13:36,738 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Topometrix
2012-05-03 15:13:36,742 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: UBM
2012-05-03 15:13:36,743 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Quesant
2012-05-03 15:13:36,744 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: BioRadGel
2012-05-03 15:13:36,748 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: RHK
2012-05-03 15:13:36,749 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: MolecularImaging
2012-05-03 15:13:36,751 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: CellWorx
2012-05-03 15:13:36,753 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Ecat7
2012-05-03 15:13:36,757 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: VarianFDF
2012-05-03 15:13:36,760 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: AIM
2012-05-03 15:13:36,762 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: InCell3000
2012-05-03 15:13:36,763 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Spider
2012-05-03 15:13:36,769 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Volocity
2012-05-03 15:13:36,774 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Imagic
2012-05-03 15:13:36,775 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: HamamatsuVMS
2012-05-03 15:13:36,776 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: CellSens
2012-05-03 15:13:36,777 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: INR
2012-05-03 15:13:36,781 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Kodak
2012-05-03 15:13:36,782 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: VolocityClipping
2012-05-03 15:13:36,788 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: ZeissCZI
2012-05-03 15:13:36,789 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: SIF
2012-05-03 15:13:36,792 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: NDPIS
2012-05-03 15:13:36,793 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Povray
2012-05-03 15:13:36,794 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: JEOL
2012-05-03 15:13:36,799 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Nifti
2012-05-03 15:13:36,800 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Companion/Nifti
2012-05-03 15:13:36,801 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Analyze
2012-05-03 15:13:36,802 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Companion/Analyze
2012-05-03 15:13:36,803 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: APL
2012-05-03 15:13:36,808 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Companion/APL
2012-05-03 15:13:36,811 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Amira
2012-05-03 15:13:36,815 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Scanr
2012-05-03 15:13:36,821 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Companion/Scanr
2012-05-03 15:13:36,822 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: BD
2012-05-03 15:13:36,827 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Unisoku
2012-05-03 15:13:36,828 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: PDS
2012-05-03 15:13:36,829 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Fuji
2012-05-03 15:13:36,830 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Operetta
2012-05-03 15:13:36,837 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: JPEG2000
2012-05-03 15:13:36,838 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: JPX
2012-05-03 15:13:36,847 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Imacon
2012-05-03 15:13:36,848 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: LEO
2012-05-03 15:13:36,849 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: JPK
2012-05-03 15:13:36,850 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: NDPI
2012-05-03 15:13:36,859 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: NikonTiff
2012-05-03 15:13:36,861 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: PhotoshopTiff
2012-05-03 15:13:36,870 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: FEITiff
2012-05-03 15:13:36,871 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: SimplePCITiff
2012-05-03 15:13:36,872 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: NikonElementsTiff
2012-05-03 15:13:36,873 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Trestle
2012-05-03 15:13:36,874 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: SIS
2012-05-03 15:13:36,876 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: DNG
2012-05-03 15:13:36,881 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: TiffDelegate
2012-05-03 15:13:36,883 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Text
2012-05-03 15:13:36,884 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Burleigh
2012-05-03 15:13:36,889 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: SMCamera
2012-05-03 15:13:36,893 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: SBIG
2012-05-03 15:13:36,894 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: HRDGDF
2012-05-03 15:13:36,895 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Hitachi
2012-05-03 15:13:36,896 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: Bruker
2012-05-03 15:13:36,899 INFO  [           ome.services.util.DBEnumCheck] (      main) Added format: CanonRaw
2012-05-03 15:13:36,902 INFO  [    ome.services.util.ServerVersionCheck] (      main) -------------------------------------------------
2012-05-03 15:13:36,902 INFO  [    ome.services.util.ServerVersionCheck] (      main) OMERO Version: 4.3.3-1458-48edaf0-ice33-b2989 Ready.
2012-05-03 15:13:36,902 INFO  [    ome.services.util.ServerVersionCheck] (      main) -------------------------------------------------
2012-05-03 15:13:38,347 WARN  [                 ome.system.UpgradeCheck] (      main) UPGRADE AVAILABLE:Please upgrade to Beta-4.3.4 See http://trac.openmicroscopy.org.uk/omero for the latest version
2012-05-03 15:13:38,358 INFO  [    ome.tools.hibernate.ExtendedMetadata] (      main) Calculating ExtendedMetadata...
2012-05-03 15:13:38,487 INFO  [.services.scheduler.SchedulerFactoryBean] (      main) Starting Quartz Scheduler now
2012-05-03 15:13:38,508 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.util.NamespaceCheck.namespaceCheck
2012-05-03 15:13:38,508 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@21168790]
2012-05-03 15:13:39,236 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=1(Internal),sess=5d834cb1-7ba8-41c4-af54-93d194d9be19
2012-05-03 15:13:39,469 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.meta.Namespace,1
2012-05-03 15:13:39,470 INFO  [        ome.services.util.NamespaceCheck] (      main) Created namespace in common space: openmicroscopy.org/omero/analysis/flim
2012-05-03 15:13:39,492 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054418508] time[984] tag[omero.call.success.ome.services.util.NamespaceCheck$1.doWork]
2012-05-03 15:13:39,492 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    null
2012-05-03 15:13:39,703 INFO  [e.services.blitz.util.BlitzConfiguration] (      main) Initializing Ice.Communicator
2012-05-03 15:13:40,490 INFO  [            ome.services.blitz.fire.Ring] (      main) Checking cluster
2012-05-03 15:13:40,540 INFO  [        ome.services.blitz.fire.Registry] (      main) Found 0 cluster node(s) : []
2012-05-03 15:13:40,540 INFO  [            ome.services.blitz.fire.Ring] (      main) Got 0 cluster uuids : []
2012-05-03 15:13:40,551 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.getManagerList
2012-05-03 15:13:40,551 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@21168790]
2012-05-03 15:13:40,560 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=null(Internal),sess=5d834cb1-7ba8-41c4-af54-93d194d9be19
2012-05-03 15:13:40,576 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054420551] time[25] tag[omero.call.success.ome.services.blitz.fire.Ring$2.doWork]
2012-05-03 15:13:40,576 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    ()
2012-05-03 15:13:40,577 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.addManager
2012-05-03 15:13:40,582 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@21168790]
2012-05-03 15:13:40,624 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=2(Internal),sess=5d834cb1-7ba8-41c4-af54-93d194d9be19
2012-05-03 15:13:40,642 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.meta.Node,1
2012-05-03 15:13:40,868 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054420583] time[285] tag[omero.call.success.ome.services.blitz.fire.Ring$5.doWork]
2012-05-03 15:13:40,871 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    ome.model.meta.Node:Id_1
2012-05-03 15:13:41,077 INFO  [        ome.services.blitz.fire.Registry] (      main) Added ClusterNode/5d834cb1-7ba8-41c4-af54-93d194d9be19 to registry
2012-05-03 15:13:41,535 INFO  [.services.blitz.repo.AbstractRepositoryI] (      main) Initializing repository in /home/omero/OMERO.data
2012-05-03 15:13:41,605 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.scripts.ScriptRepoHelper.loadAll(true)
2012-05-03 15:13:41,605 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@21168790]

2012-05-03 15:13:41,658 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=3(Internal),sess=5d834cb1-7ba8-41c4-af54-93d194d9be19
2012-05-03 15:13:41,744 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,1
2012-05-03 15:13:41,798 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,2
2012-05-03 15:13:41,866 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,3
2012-05-03 15:13:41,916 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,4
2012-05-03 15:13:41,945 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,5
2012-05-03 15:13:41,979 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,6
2012-05-03 15:13:42,051 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,7
2012-05-03 15:13:42,104 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,8
2012-05-03 15:13:42,135 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,9
2012-05-03 15:13:42,180 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,10
2012-05-03 15:13:42,224 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,11
2012-05-03 15:13:42,265 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,12
2012-05-03 15:13:42,320 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.core.OriginalFile,13
2012-05-03 15:13:42,411 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336054421609] time[802] tag[omero.call.success.ome.services.scripts.ScriptRepoHelper$5.doWork]
2012-05-03 15:13:42,415 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    (ome.model.core.OriginalFile:Id_1, ome.model.core.OriginalFile:Id_2, ome.model.core.OriginalFile:Id_3, ... 10 more)
2012-05-03 15:13:42,417 INFO  [.services.blitz.repo.AbstractRepositoryI] (      main) Initializing repository in /home/omero/OMERO.server/./lib/scripts
2012-05-03 15:13:42,731 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Executor.doWork -- ome.services.blitz.repo.ScriptRepositoryI.takeover
2012-05-03 15:13:42,732 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Args:    [null, InternalSF@21168790]
2012-05-03 15:13:42,736 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Executor.doWork -- ome.services.blitz.repo.LegacyRepositoryI.takeover
2012-05-03 15:13:42,736 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Args:    [null, InternalSF@21168790]
2012-05-03 15:13:42,847 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Found location in errorTimes: -1
2012-05-03 15:13:42,847 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Removing 0 from errorTimes
2012-05-03 15:13:42,847 WARN  [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Registering error with list: Current size: 0
2012-05-03 15:13:42,847 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Sleeping for 0 then retry: 1
2012-05-03 15:13:42,867 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Found location in errorTimes: -1
2012-05-03 15:13:42,867 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Removing 0 from errorTimes
2012-05-03 15:13:42,867 WARN  [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Registering error with list: Current size: 1
2012-05-03 15:13:42,867 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Sleeping for 1000 then retry: 2
2012-05-03 15:13:42,933 INFO  [                ome.services.blitz.Entry] (      main) OMERO.blitz now accepting connections.
2012-05-03 15:13:42,934 INFO  [    ome.services.blitz.util.CheckAllJobs] (  Thread-8) Waiting 120 secs. for callbacks
2012-05-03 15:13:43,559 INFO  [        ome.services.util.ServiceHandler] (l.Server-4)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2012-05-03 15:13:43,560 INFO  [        ome.services.util.ServiceHandler] (l.Server-4)  Args:    [null, InternalSF@21168790]
2012-05-03 15:13:43,568 INFO  [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Found location in errorTimes: -1
2012-05-03 15:13:43,568 INFO  [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Removing 0 from errorTimes
2012-05-03 15:13:43,568 WARN  [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Registering error with list: Current size: 2
2012-05-03 15:13:43,568 INFO  [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Sleeping for 1000 then retry: 1
2012-05-03 15:13:43,795 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Found location in errorTimes: -1
2012-05-03 15:13:43,795 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Removing 0 from errorTimes
2012-05-03 15:13:43,795 WARN  [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Registering error with list: Current size: 3
2012-05-03 15:13:43,795 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Sleeping for 2000 then retry: 1
2012-05-03 15:13:43,869 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Found location in errorTimes: -1
2012-05-03 15:13:43,869 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Removing 0 from errorTimes
2012-05-03 15:13:43,869 WARN  [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Registering error with list: Current size: 4
2012-05-03 15:13:43,873 ERROR [ome.services.db.SelfCorrectingDataSource] (2-thread-2) Failed to acquire connection after retries=3
java.sql.SQLException: unable to get a connection from pool of a PoolingDataSource containing an XAPool of resource 5d834cb1-7ba8-41c4-af54-93d194d9be19 with 0 connection(s) (0 still available)
        at bitronix.tm.resource.jdbc.PoolingDataSource.getConnection(PoolingDataSource.java:201)
        at org.springframework.jdbc.datasource.DelegatingDataSource.getConnection(DelegatingDataSource.java:83)
        at ome.services.db.SelfCorrectingDataSource.call(SelfCorrectingDataSource.java:102)
        at ome.services.db.SelfCorrectingDataSource.callWithRetries(SelfCorrectingDataSource.java:75)
        at ome.services.db.SelfCorrectingDataSource.getConnection(SelfCorrectingDataSource.java:59)
        at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:203)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:354)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:103)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:231)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:116)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy65.doWork(Unknown Source)
        at ome.services.util.Executor$Impl.execute(Executor.java:402)
        at ome.services.util.Executor$Impl.execute(Executor.java:346)
        at ome.services.blitz.repo.AbstractRepositoryI.takeover(AbstractRepositoryI.java:120)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
        at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:264)
        at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:203)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)

Caused by: java.sql.SQLException: unable to connect to non-XA resource org.postgresql.Driver
        at bitronix.tm.resource.jdbc.lrc.LrcXADataSource.getXAConnection(LrcXADataSource.java:106)
        at bitronix.tm.resource.jdbc.PoolingDataSource.createPooledConnection(PoolingDataSource.java:274)
        at bitronix.tm.resource.common.XAPool.createPooledObject(XAPool.java:283)
        at bitronix.tm.resource.common.XAPool.grow(XAPool.java:400)
        at bitronix.tm.resource.common.XAPool.getInPool(XAPool.java:379)
        at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:123)
        at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:91)
        at bitronix.tm.resource.jdbc.PoolingDataSource.getConnection(PoolingDataSource.java:197)
        ... 29 more
Caused by: org.postgresql.util.PSQLException: Connection refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
        at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:138)
        at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:66)
        at org.postgresql.jdbc2.AbstractJdbc2Connection.<init>(AbstractJdbc2Connection.java:125)
        at org.postgresql.jdbc3.AbstractJdbc3Connection.<init>(AbstractJdbc3Connection.java:30)
        at org.postgresql.jdbc3.Jdbc3Connection.<init>(Jdbc3Connection.java:24)
        at org.postgresql.Driver.makeConnection(Driver.java:393)
        at org.postgresql.Driver.connect(Driver.java:267)
        at bitronix.tm.resource.jdbc.lrc.LrcXADataSource.getXAConnection(LrcXADataSource.java:102)
        ... 36 more
Caused by: java.net.ConnectException: Connection refused
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
        at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
        at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
        at java.net.Socket.connect(Socket.java:529)
        at java.net.Socket.connect(Socket.java:478)
        at java.net.Socket.<init>(Socket.java:375)
        at java.net.Socket.<init>(Socket.java:189)
        at org.postgresql.core.PGStream.<init>(PGStream.java:62)
        at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:76)
        ... 43 more
2012-05-03 15:13:43,875 INFO  [                 org.perf4j.TimingLogger] (2-thread-2) start[1336054422736] time[1139] tag[omero.call.exception]
2012-05-03 15:13:43,878 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Excp:    ome.conditions.DatabaseBusyException: Cannot acquire connection
2012-05-03 15:13:43,878 ERROR [.services.blitz.repo.AbstractRepositoryI] (2-thread-2) Unexpected error in called executor on takeover
ome.conditions.DatabaseBusyException: Cannot acquire connection
        at ome.services.db.SelfCorrectingDataSource.callWithRetries(SelfCorrectingDataSource.java:91)
        at ome.services.db.SelfCorrectingDataSource.getConnection(SelfCorrectingDataSource.java:59)
        at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:203)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:354)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:103)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:231)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:116)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy65.doWork(Unknown Source)
        at ome.services.util.Executor$Impl.execute(Executor.java:402)
        at ome.services.util.Executor$Impl.execute(Executor.java:346)
        at ome.services.blitz.repo.AbstractRepositoryI.takeover(AbstractRepositoryI.java:120)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
        at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:264)
        at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:203)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)

2012-05-03 15:13:44,572 INFO  [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Found location in errorTimes: -1
2012-05-03 15:13:44,572 INFO  [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Removing 0 from errorTimes
2012-05-03 15:13:44,572 WARN  [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Registering error with list: Current size: 5
2012-05-03 15:13:44,572 INFO  [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Sleeping for 2000 then retry: 2
2012-05-03 15:13:45,800 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Found location in errorTimes: -1
2012-05-03 15:13:45,801 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Removing 0 from errorTimes
2012-05-03 15:13:45,801 WARN  [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Registering error with list: Current size: 6
2012-05-03 15:13:45,801 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Sleeping for 2000 then retry: 2
2012-05-03 15:13:46,573 INFO  [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Found location in errorTimes: -1
2012-05-03 15:13:46,573 INFO  [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Removing 0 from errorTimes
2012-05-03 15:13:46,573 WARN  [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Registering error with list: Current size: 7
2012-05-03 15:13:46,573 ERROR [ome.services.db.SelfCorrectingDataSource] (l.Server-4) Failed to acquire connection after retries=3
java.sql.SQLException: unable to get a connection from pool of a PoolingDataSource containing an XAPool of resource 5d834cb1-7ba8-41c4-af54-93d194d9be19 with 0 connection(s) (0 still available)
        at bitronix.tm.resource.jdbc.PoolingDataSource.getConnection(PoolingDataSource.java:201)
        at org.springframework.jdbc.datasource.DelegatingDataSource.getConnection(DelegatingDataSource.java:83)
        at ome.services.db.SelfCorrectingDataSource.call(SelfCorrectingDataSource.java:102)
        at ome.services.db.SelfCorrectingDataSource.callWithRetries(SelfCorrectingDataSource.java:75)
        at ome.services.db.SelfCorrectingDataSource.getConnection(SelfCorrectingDataSource.java:59)
        at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:203)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:354)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:103)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:231)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:116)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy65.doWork(Unknown Source)
        at ome.services.util.Executor$Impl.execute(Executor.java:402)
        at ome.services.util.Executor$Impl.execute(Executor.java:346)
        at ome.services.sessions.SessionManagerImpl.createSession(SessionManagerImpl.java:300)
        at ome.services.sessions.SessionManagerImpl.createWithAgent(SessionManagerImpl.java:252)
        at ome.services.blitz.fire.SessionManagerI.create(SessionManagerI.java:174)
        at Glacier2._SessionManagerDisp.___create(_SessionManagerDisp.java:92)
        at Glacier2._SessionManagerDisp.__dispatch(_SessionManagerDisp.java:125)
        at IceInternal.Incoming.invoke(Incoming.java:159)
        at Ice.ConnectionI.invokeAll(ConnectionI.java:2037)
        at Ice.ConnectionI.message(ConnectionI.java:972)
        at IceInternal.ThreadPool.run(ThreadPool.java:577)
        at IceInternal.ThreadPool.access$100(ThreadPool.java:12)
        at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:971)

Caused by: java.sql.SQLException: unable to connect to non-XA resource org.postgresql.Driver
        at bitronix.tm.resource.jdbc.lrc.LrcXADataSource.getXAConnection(LrcXADataSource.java:106)
        at bitronix.tm.resource.jdbc.PoolingDataSource.createPooledConnection(PoolingDataSource.java:274)
        at bitronix.tm.resource.common.XAPool.createPooledObject(XAPool.java:283)
        at bitronix.tm.resource.common.XAPool.grow(XAPool.java:400)
        at bitronix.tm.resource.common.XAPool.getInPool(XAPool.java:379)
        at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:123)
        at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:91)
        at bitronix.tm.resource.jdbc.PoolingDataSource.getConnection(PoolingDataSource.java:197)
        ... 28 more
Caused by: org.postgresql.util.PSQLException: Connection refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
        at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:138)
        at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:66)
        at org.postgresql.jdbc2.AbstractJdbc2Connection.<init>(AbstractJdbc2Connection.java:125)
        at org.postgresql.jdbc3.AbstractJdbc3Connection.<init>(AbstractJdbc3Connection.java:30)
        at org.postgresql.jdbc3.Jdbc3Connection.<init>(Jdbc3Connection.java:24)
        at org.postgresql.Driver.makeConnection(Driver.java:393)
        at org.postgresql.Driver.connect(Driver.java:267)
        at bitronix.tm.resource.jdbc.lrc.LrcXADataSource.getXAConnection(LrcXADataSource.java:102)
        ... 35 more
Caused by: java.net.ConnectException: Connection refused
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
        at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
        at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
        at java.net.Socket.connect(Socket.java:529)
        at java.net.Socket.connect(Socket.java:478)
        at java.net.Socket.<init>(Socket.java:375)
        at java.net.Socket.<init>(Socket.java:189)
        at org.postgresql.core.PGStream.<init>(PGStream.java:62)
        at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:76)
        ... 42 more
2012-05-03 15:13:46,575 INFO  [                 org.perf4j.TimingLogger] (l.Server-4) start[1336054423560] time[3015] tag[omero.call.exception]
2012-05-03 15:13:46,575 INFO  [        ome.services.util.ServiceHandler] (l.Server-4)  Excp:    ome.conditions.DatabaseBusyException: Cannot acquire connection
2012-05-03 15:13:46,579 INFO  [                ome.services.blitz.Entry] (      main) Calling close on context OMERO.blitz
2012-05-03 15:13:46,581 INFO  [.services.blitz.repo.AbstractRepositoryI] (      main) Releasing /home/omero/OMERO.server/./lib/scripts
2012-05-03 15:13:46,581 INFO  [.services.blitz.repo.AbstractRepositoryI] (      main) Releasing /home/omero/OMERO.data
2012-05-03 15:13:46,585 INFO  [        ome.services.blitz.fire.Registry] (      main) Removed ClusterNode/5d834cb1-7ba8-41c4-af54-93d194d9be19 from registry
2012-05-03 15:13:46,586 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.executeUpdate - set closed = now()
2012-05-03 15:13:46,586 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@21168790]
2012-05-03 15:13:46,587 INFO  [ome.services.db.SelfCorrectingDataSource] (      main) Found location in errorTimes: -1
2012-05-03 15:13:46,587 INFO  [ome.services.db.SelfCorrectingDataSource] (      main) Removing 0 from errorTimes
2012-05-03 15:13:46,587 WARN  [ome.services.db.SelfCorrectingDataSource] (      main) Registering error with list: Current size: 8
2012-05-03 15:13:46,587 INFO  [ome.services.db.SelfCorrectingDataSource] (      main) Sleeping for 3000 then retry: 1
2012-05-03 15:13:47,801 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Found location in errorTimes: -1
2012-05-03 15:13:47,802 INFO  [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Removing 0 from errorTimes
2012-05-03 15:13:47,802 WARN  [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Registering error with list: Current size: 9
2012-05-03 15:13:47,802 ERROR [ome.services.db.SelfCorrectingDataSource] (2-thread-3) Failed to acquire connection after retries=3
java.sql.SQLException: unable to get a connection from pool of a PoolingDataSource containing an XAPool of resource 5d834cb1-7ba8-41c4-af54-93d194d9be19 with 0 connection(s) (0 still available)

        at bitronix.tm.resource.jdbc.PoolingDataSource.getConnection(PoolingDataSource.java:201)
        at org.springframework.jdbc.datasource.DelegatingDataSource.getConnection(DelegatingDataSource.java:83)
        at ome.services.db.SelfCorrectingDataSource.call(SelfCorrectingDataSource.java:102)
        at ome.services.db.SelfCorrectingDataSource.callWithRetries(SelfCorrectingDataSource.java:75)
        at ome.services.db.SelfCorrectingDataSource.getConnection(SelfCorrectingDataSource.java:59)
        at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:203)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:354)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:103)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:231)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:116)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy65.doWork(Unknown Source)
        at ome.services.util.Executor$Impl.execute(Executor.java:402)
        at ome.services.util.Executor$Impl.execute(Executor.java:346)
        at ome.services.blitz.repo.AbstractRepositoryI.takeover(AbstractRepositoryI.java:120)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
        at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:264)
        at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:203)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
Caused by: java.sql.SQLException: unable to connect to non-XA resource org.postgresql.Driver
        at bitronix.tm.resource.jdbc.lrc.LrcXADataSource.getXAConnection(LrcXADataSource.java:106)
        at bitronix.tm.resource.jdbc.PoolingDataSource.createPooledConnection(PoolingDataSource.java:274)
        at bitronix.tm.resource.common.XAPool.createPooledObject(XAPool.java:283)
        at bitronix.tm.resource.common.XAPool.grow(XAPool.java:400)
        at bitronix.tm.resource.common.XAPool.getInPool(XAPool.java:379)
        at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:123)
        at bitronix.tm.resource.common.XAPool.getConnectionHandle(XAPool.java:91)
        at bitronix.tm.resource.jdbc.PoolingDataSource.getConnection(PoolingDataSource.java:197)
        ... 29 more
Caused by: org.postgresql.util.PSQLException: Connection refused. Check that the hostname and port are correct and that the postmaster is accepting TCP/IP connections.
        at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:138)
        at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:66)
        at org.postgresql.jdbc2.AbstractJdbc2Connection.<init>(AbstractJdbc2Connection.java:125)
        at org.postgresql.jdbc3.AbstractJdbc3Connection.<init>(AbstractJdbc3Connection.java:30)
        at org.postgresql.jdbc3.Jdbc3Connection.<init>(Jdbc3Connection.java:24)
        at org.postgresql.Driver.makeConnection(Driver.java:393)
        at org.postgresql.Driver.connect(Driver.java:267)
        at bitronix.tm.resource.jdbc.lrc.LrcXADataSource.getXAConnection(LrcXADataSource.java:102)
        ... 36 more
Caused by: java.net.ConnectException: Connection refused
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:351)
        at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:213)
        at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:200)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
        at java.net.Socket.connect(Socket.java:529)
        at java.net.Socket.connect(Socket.java:478)
        at java.net.Socket.<init>(Socket.java:375)
        at java.net.Socket.<init>(Socket.java:189)
        at org.postgresql.core.PGStream.<init>(PGStream.java:62)
        at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:76)
        ... 43 more

2012-05-03 15:13:47,803 INFO  [                 org.perf4j.TimingLogger] (2-thread-3) start[1336054422732] time[5071] tag[omero.call.exception]
2012-05-03 15:13:47,804 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Excp:    ome.conditions.DatabaseBusyException: Cannot acquire connection
2012-05-03 15:13:47,804 WARN  [        ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 5071
2012-05-03 15:13:47,805 ERROR [.services.blitz.repo.AbstractRepositoryI] (2-thread-3) Unexpected error in called executor on takeover
ome.conditions.DatabaseBusyException: Cannot acquire connection
        at ome.services.db.SelfCorrectingDataSource.callWithRetries(SelfCorrectingDataSource.java:91)
        at ome.services.db.SelfCorrectingDataSource.getConnection(SelfCorrectingDataSource.java:59)
        at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:203)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:354)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:103)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:231)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:116)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy65.doWork(Unknown Source)
        at ome.services.util.Executor$Impl.execute(Executor.java:402)
        at ome.services.util.Executor$Impl.execute(Executor.java:346)
        at ome.services.blitz.repo.AbstractRepositoryI.takeover(AbstractRepositoryI.java:120)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.springframework.util.MethodInvoker.invoke(MethodInvoker.java:273)
        at org.springframework.scheduling.quartz.MethodInvokingJobDetailFactoryBean$MethodInvokingJob.executeInternal(MethodInvokingJobDetailFactoryBean.java:264)
        at org.springframework.scheduling.quartz.QuartzJobBean.execute(QuartzJobBean.java:86)
        at org.quartz.core.JobRunShell.run(JobRunShell.java:203)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:662)
2012-05-10 11:25:32,271 INFO  [                ome.services.blitz.Entry] (      main) Creating OMERO.blitz. Please wait...
2012-05-10 11:25:35,555 INFO  [ng.ShutdownSafeEhcacheManagerFactoryBean] (      main) Initializing EHCache CacheManager
2012-05-10 11:25:37,228 INFO  [          ome.services.util.DBPatchCheck] (      main) Verified database patch: OMERO4.3__0
2012-05-10 11:25:43,257 INFO  [  ome.services.fulltext.FullTextAnalyzer] (      main) Initialized FullTextAnalyzer
2012-05-10 11:25:51,398 INFO  [        ome.services.db.DatabaseIdentity] (      main) Using LSID format: urn:lsid:export.openmicroscopy.org:%s:de968e1e-1f1c-411d-921b-48206f5ea301_%s%s
2012-05-10 11:25:52,931 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645551485] time[1446] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:53,148 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645552941] time[207] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:53,337 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645553148] time[189] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:53,536 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645553337] time[199] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:53,762 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645553540] time[222] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:54,178 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645553765] time[413] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:54,351 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645554179] time[172] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:54,597 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645554364] time[233] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:54,828 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645554604] time[224] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:55,729 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645554828] time[901] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:55,854 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645555730] time[124] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:55,986 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645555855] time[131] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:56,123 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645555986] time[137] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:56,248 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645556123] time[125] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:56,373 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645556249] time[124] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:56,511 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645556373] time[138] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:56,808 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645556513] time[295] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:56,923 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645556809] time[114] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:57,042 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645556926] time[116] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:57,168 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645557047] time[121] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:25:57,181 INFO  [                ome.io.nio.PixelsService] (      main) PixelsService(path=/home/omero/OMERO.data, resolver=ome.services.OmeroFilePathResolver@47122d, backoff=ome.io.nio.SimpleBackOff(factor=142.5), sizes=ome.io.nio.ConfiguredTileSizes(w=256,h=256,W=3192,H=3192))

2012-05-10 11:25:57,510 INFO  [    ome.services.fulltext.FullTextThread] (      main) Initializing Full-Text Indexer
2012-05-10 11:25:57,524 INFO  [  ome.services.pixeldata.PixelDataThread] (      main) Initializing PixelDataThread (create events only)
2012-05-10 11:25:58,315 INFO  [    ome.services.util.ServerVersionCheck] (      main) -------------------------------------------------
2012-05-10 11:25:58,315 INFO  [    ome.services.util.ServerVersionCheck] (      main) OMERO Version: 4.3.3-1458-48edaf0-ice33-b2989 Ready.
2012-05-10 11:25:58,315 INFO  [    ome.services.util.ServerVersionCheck] (      main) -------------------------------------------------
2012-05-10 11:26:08,423 ERROR [                 ome.system.UpgradeCheck] (      main) Error reading from url: http://upgrade.openmicroscopy.org.uk?version=4.3.3-1458-48edaf0-ice33-b2989;os.name=Linux;os.arch=i386;os.version=2.6.32-5-686;java.runtime.version=1.6.0_26-b03;
java.vm.vendor=Sun+Microsystems+Inc. "connect timed out"
2012-05-10 11:26:08,426 INFO  [    ome.tools.hibernate.ExtendedMetadata] (      main) Calculating ExtendedMetadata...
2012-05-10 11:26:08,510 INFO  [.services.scheduler.SchedulerFactoryBean] (      main) Starting Quartz Scheduler now
2012-05-10 11:26:08,514 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.util.NamespaceCheck.namespaceCheck
2012-05-10 11:26:08,514 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:09,153 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=51(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:09,285 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645568515] time[770] tag[omero.call.success.ome.services.util.NamespaceCheck$1.doWork]
2012-05-10 11:26:09,285 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    null
2012-05-10 11:26:09,529 INFO  [e.services.blitz.util.BlitzConfiguration] (      main) Initializing Ice.Communicator
2012-05-10 11:26:09,641 INFO  [            ome.services.blitz.fire.Ring] (      main) Checking cluster
2012-05-10 11:26:09,669 INFO  [        ome.services.blitz.fire.Registry] (      main) Found 0 cluster node(s) : []
2012-05-10 11:26:09,670 INFO  [            ome.services.blitz.fire.Ring] (      main) Got 0 cluster uuids : []
2012-05-10 11:26:09,673 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.getManagerList


[Thorondor]

Code: Select all

2012-05-10 11:26:09,673 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:09,677 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=null(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:09,686 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645569673] time[13] tag[omero.call.success.ome.services.blitz.fire.Ring$2.doWork]
2012-05-10 11:26:09,686 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    (5d834cb1-7ba8-41c4-af54-93d194d9be19)
2012-05-10 11:26:09,686 INFO  [            ome.services.blitz.fire.Ring] (      main) Purging node: 5d834cb1-7ba8-41c4-af54-93d194d9be19
2012-05-10 11:26:09,954 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.executeUpdate - set closed = now()
2012-05-10 11:26:09,954 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:09,972 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=52(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:09,978 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645569954] time[24] tag[omero.call.success.ome.services.blitz.fire.Ring$3.doWork]
2012-05-10 11:26:09,978 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    0
2012-05-10 11:26:09,978 INFO  [            ome.services.blitz.fire.Ring] (      main) Removed 0 entries with value 5d834cb1-7ba8-41c4-af54-93d194d9be19
2012-05-10 11:26:09,979 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.setManagerDown
2012-05-10 11:26:09,979 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:09,990 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=53(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:10,015 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645569979] time[36] tag[omero.call.success.ome.services.blitz.fire.Ring$4.doWork]
2012-05-10 11:26:10,015 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    1
2012-05-10 11:26:10,016 INFO  [            ome.services.blitz.fire.Ring] (      main) Removed manager: 5d834cb1-7ba8-41c4-af54-93d194d9be19
2012-05-10 11:26:10,016 INFO  [            ome.services.blitz.fire.Ring] (      main) handleRingShutdown: 5d834cb1-7ba8-41c4-af54-93d194d9be19
2012-05-10 11:26:10,016 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.addManager
2012-05-10 11:26:10,016 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:10,035 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=54(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:10,064 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.meta.Node,51
2012-05-10 11:26:10,118 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645570016] time[102] tag[omero.call.success.ome.services.blitz.fire.Ring$5.doWork]
2012-05-10 11:26:10,119 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    ome.model.meta.Node:Id_51
2012-05-10 11:26:10,122 INFO  [        ome.services.blitz.fire.Registry] (      main) Added ClusterNode/8a7f8f70-67c6-4316-ad16-dd826eab6c10 to registry
2012-05-10 11:26:10,357 INFO  [.services.blitz.repo.AbstractRepositoryI] (      main) Initializing repository in /home/omero/OMERO.data
2012-05-10 11:26:10,392 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.scripts.ScriptRepoHelper.loadAll(true)
2012-05-10 11:26:10,392 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:10,409 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=55(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:10,508 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336645570392] time[116] tag[omero.call.success.ome.services.scripts.ScriptRepoHelper$5.doWork]
2012-05-10 11:26:10,508 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    (ome.model.core.OriginalFile:Id_1, ome.model.core.OriginalFile:Id_2, ome.model.core.OriginalFile:Id_3, ... 10 more)
2012-05-10 11:26:10,509 INFO  [.services.blitz.repo.AbstractRepositoryI] (      main) Initializing repository in /home/omero/OMERO.server/./lib/scripts
2012-05-10 11:26:10,587 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Executor.doWork -- ome.services.blitz.repo.LegacyRepositoryI.takeover
2012-05-10 11:26:10,589 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:10,589 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Executor.doWork -- ome.services.blitz.repo.ScriptRepositoryI.takeover
2012-05-10 11:26:10,589 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:10,628 INFO  [         ome.security.basic.EventHandler] (2-thread-1)  Auth:    user=0,group=0,event=56(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:10,631 INFO  [       ome.services.blitz.repo.FileMaker] (2-thread-1) Creating /home/omero/OMERO.data/.omero/repository/de968e1e-1f1c-411d-921b-48206f5ea301
2012-05-10 11:26:10,639 INFO  [                ome.services.blitz.Entry] (      main) OMERO.blitz now accepting connections.
2012-05-10 11:26:10,641 INFO  [    ome.services.blitz.util.CheckAllJobs] (  Thread-8) Waiting 120 secs. for callbacks

2012-05-10 11:26:10,695 INFO  [         ome.security.basic.EventHandler] (2-thread-2)  Auth:    user=0,group=0,event=57(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:10,696 INFO  [       ome.services.blitz.repo.FileMaker] (2-thread-2) Creating /home/omero/OMERO.server/./lib/scripts/.omero/repository/de968e1e-1f1c-411d-921b-48206f5ea301
2012-05-10 11:26:10,731 INFO  [       ome.security.basic.CurrentDetails] (2-thread-1) Adding log:INSERT,class ome.model.core.OriginalFile,51
2012-05-10 11:26:10,734 INFO  [       ome.security.basic.CurrentDetails] (2-thread-2) Adding log:INSERT,class ome.model.core.OriginalFile,52
2012-05-10 11:26:10,735 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(8a7f8f70-67c6-4316-ad16-dd826eab6c10)
2012-05-10 11:26:10,735 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:10,738 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.reload(8a7f8f70-67c6-4316-ad16-dd826eab6c10)
2012-05-10 11:26:10,738 INFO  [        ome.services.util.ServiceHandler] (2-thread-4)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:10,743 INFO  [         ome.security.basic.EventHandler] (2-thread-3)  Auth:    user=0,group=0,event=null(Sessions),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:10,756 INFO  [         ome.security.basic.EventHandler] (2-thread-4)  Auth:    user=0,group=0,event=null(Sessions),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:10,793 INFO  [                 org.perf4j.TimingLogger] (2-thread-3) start[1336645570735] time[58] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2012-05-10 11:26:10,793 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Rslt:    (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2012-05-10 11:26:10,793 INFO  [                 org.perf4j.TimingLogger] (2-thread-4) start[1336645570738] time[55] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
2012-05-10 11:26:10,795 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)
2012-05-10 11:26:10,820 INFO  [       ome.security.basic.CurrentDetails] (2-thread-1) Adding log:UPDATE,class ome.model.core.OriginalFile,51
2012-05-10 11:26:10,820 INFO  [                     ome.logic.AdminImpl] (2-thread-1) Moved object to common space: ome.model.core.OriginalFile:Id_51
2012-05-10 11:26:10,821 INFO  [       ome.security.basic.CurrentDetails] (2-thread-2) Adding log:UPDATE,class ome.model.core.OriginalFile,52
2012-05-10 11:26:10,820 INFO  [.services.blitz.repo.AbstractRepositoryI] (2-thread-1) Registered new repository OMERO.data (uuid=db95988d-2735-462e-81ae-2467b0a8e15d)
2012-05-10 11:26:10,821 INFO  [.services.blitz.repo.AbstractRepositoryI] (2-thread-1) Opened repository OMERO.data (uuid=db95988d-2735-462e-81ae-2467b0a8e15d)
2012-05-10 11:26:10,821 INFO  [                     ome.logic.AdminImpl] (2-thread-2) Moved object to common space: ome.model.core.OriginalFile:Id_52
2012-05-10 11:26:10,821 INFO  [.services.blitz.repo.AbstractRepositoryI] (2-thread-2) Registered new repository scripts (uuid=ScriptRepo)
2012-05-10 11:26:10,821 INFO  [.services.blitz.repo.AbstractRepositoryI] (2-thread-2) Opened repository scripts (uuid=ScriptRepo)
2012-05-10 11:26:10,859 INFO  [        ome.services.blitz.fire.Registry] (2-thread-1) Added InternalRepository-db95988d-2735-462e-81ae-2467b0a8e15d to registry
2012-05-10 11:26:10,861 INFO  [        ome.services.blitz.fire.Registry] (2-thread-1) Added PublicRepository-db95988d-2735-462e-81ae-2467b0a8e15d to registry
2012-05-10 11:26:10,865 INFO  [.services.blitz.repo.AbstractRepositoryI] (2-thread-1) Repository now active
2012-05-10 11:26:10,868 INFO  [        ome.services.blitz.fire.Registry] (2-thread-2) Added InternalRepository-ScriptRepo to registry
2012-05-10 11:26:10,870 INFO  [        ome.services.blitz.fire.Registry] (2-thread-2) Added PublicRepository-ScriptRepo to registry
2012-05-10 11:26:10,870 INFO  [.services.blitz.repo.AbstractRepositoryI] (2-thread-2) Repository now active
2012-05-10 11:26:10,879 INFO  [                 org.perf4j.TimingLogger] (2-thread-2) start[1336645570589] time[290] tag[omero.call.success.ome.services.blitz.repo.AbstractRepositoryI$GetOrCreateRepo.doWork]
2012-05-10 11:26:10,880 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Rslt:    ome.model.core.OriginalFile:Id_52
2012-05-10 11:26:10,881 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Executor.doWork -- ome.services.blitz.repo.ScriptRepositoryI.getDescription(52)
2012-05-10 11:26:10,881 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:10,882 INFO  [                 org.perf4j.TimingLogger] (2-thread-1) start[1336645570589] time[293] tag[omero.call.success.ome.services.blitz.repo.AbstractRepositoryI$GetOrCreateRepo.doWork]
2012-05-10 11:26:10,882 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Rslt:    ome.model.core.OriginalFile:Id_51
2012-05-10 11:26:10,882 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Executor.doWork -- ome.services.blitz.repo.LegacyRepositoryI.getDescription(51)
2012-05-10 11:26:10,882 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:10,883 INFO  [         ome.security.basic.EventHandler] (2-thread-2)  Auth:    user=0,group=0,event=null(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:10,886 INFO  [         ome.security.basic.EventHandler] (2-thread-1)  Auth:    user=0,group=0,event=null(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:10,897 INFO  [                 org.perf4j.TimingLogger] (2-thread-2) start[1336645570881] time[16] tag[omero.call.success.ome.services.blitz.repo.AbstractRepositoryI$1.doWork]
2012-05-10 11:26:10,897 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Rslt:    ome.model.core.OriginalFile:Id_52
2012-05-10 11:26:10,898 INFO  [                 org.perf4j.TimingLogger] (2-thread-1) start[1336645570882] time[16] tag[omero.call.success.ome.services.blitz.repo.AbstractRepositoryI$1.doWork]
2012-05-10 11:26:10,898 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Rslt:    ome.model.core.OriginalFile:Id_51
2012-05-10 11:26:12,672 INFO  [        ome.services.util.ServiceHandler] (l.Server-7)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2012-05-10 11:26:12,672 INFO  [        ome.services.util.ServiceHandler] (l.Server-7)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:12,691 INFO  [         ome.security.basic.EventHandler] (l.Server-7)  Auth:    user=0,group=0,event=58(Sessions),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:12,735 INFO  [       ome.security.basic.CurrentDetails] (l.Server-7) Adding log:INSERT,class ome.model.meta.Session,208
2012-05-10 11:26:12,748 INFO  [                 org.perf4j.TimingLogger] (l.Server-7) start[1336645572672] time[76] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2012-05-10 11:26:12,749 INFO  [        ome.services.util.ServiceHandler] (l.Server-7)  Rslt:    (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2012-05-10 11:26:12,774 INFO  [ ome.services.blitz.fire.SessionManagerI] (l.Server-7) Created session ServiceFactoryI(session-84faa93f-d198-481e-8566-4ab02e182ada/89b8a1d8-553a-442f-ac0e-b81b27d385c9) for user root (agent=Python service)
2012-05-10 11:26:12,790 INFO  [                      omero.cmd.SessionI] (l.Server-8) Added servant to adapter: 89b8a1d8-553a-442f-ac0e-b81b27d385c9/84faa93f-d198-481e-8566-4ab02e182adaomero.api.IConfig(omero.api._IConfigTie@ad348ca)
2012-05-10 11:26:12,798 INFO  [        ome.services.util.ServiceHandler] (l.Server-1)  Meth:    interface ome.api.IConfig.getConfigValue
2012-05-10 11:26:12,798 INFO  [        ome.services.util.ServiceHandler] (l.Server-1)  Args:    [omero.data.dir]
2012-05-10 11:26:12,810 INFO  [         ome.security.basic.EventHandler] (l.Server-1)  Auth:    user=0,group=0,event=59(User),sess=89b8a1d8-553a-442f-ac0e-b81b27d385c9
2012-05-10 11:26:12,814 INFO  [                 org.perf4j.TimingLogger] (l.Server-1) start[1336645572798] time[16] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2012-05-10 11:26:12,815 INFO  [        ome.services.util.ServiceHandler] (l.Server-1)  Rslt:    /home/omero/OMERO.data
2012-05-10 11:26:12,817 INFO  [e.services.sessions.SessionContext$Count] (l.Server-5) -Reference count: 89b8a1d8-553a-442f-ac0e-b81b27d385c9=0
2012-05-10 11:26:12,818 INFO  [                      omero.cmd.SessionI] (l.Server-5) doDestroy(ServiceFactoryI(session-84faa93f-d198-481e-8566-4ab02e182ada/89b8a1d8-553a-442f-ac0e-b81b27d385c9))
2012-05-10 11:26:12,819 INFO  [                      omero.cmd.SessionI] (l.Server-5) Unregistered servant:89b8a1d8-553a-442f-ac0e-b81b27d385c9/84faa93f-d198-481e-8566-4ab02e182adaomero.api.IConfig(omero.api._IConfigTie@ad348ca)
2012-05-10 11:26:12,819 INFO  [                      omero.cmd.SessionI] (l.Server-5) Removed servant from adapter: 84faa93f-d198-481e-8566-4ab02e182adaomero.api.IConfig
2012-05-10 11:26:12,819 INFO  [ome.services.sessions.SessionManagerImpl] (l.Server-5) closeSession called and no more references: 89b8a1d8-553a-442f-ac0e-b81b27d385c9
2012-05-10 11:26:12,819 INFO  [ome.services.sessions.state.SessionCache] (l.Server-5) Destroying session 89b8a1d8-553a-442f-ac0e-b81b27d385c9 due to : Remove session called
2012-05-10 11:26:12,819 INFO  [                 org.perf4j.TimingLogger] (l.Server-5) start[1336645572749] time[70] tag[omero.session]
2012-05-10 11:26:12,822 INFO  [ ome.services.blitz.fire.SessionManagerI] (l.Server-5) Reaping 1 clients for 89b8a1d8-553a-442f-ac0e-b81b27d385c9
2012-05-10 11:26:19,657 INFO  [        ome.services.util.ServiceHandler] (l.Server-3)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2012-05-10 11:26:19,657 INFO  [        ome.services.util.ServiceHandler] (l.Server-3)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:19,661 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2012-05-10 11:26:19,661 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Args:    [null, InternalSF@7793709]
2012-05-10 11:26:19,680 INFO  [         ome.security.basic.EventHandler] (l.Server-3)  Auth:    user=0,group=0,event=60(Sessions),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:19,686 INFO  [         ome.security.basic.EventHandler] (l.Server-9)  Auth:    user=0,group=0,event=61(Sessions),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:26:19,707 INFO  [       ome.security.basic.CurrentDetails] (l.Server-3) Adding log:INSERT,class ome.model.meta.Session,210
2012-05-10 11:26:19,709 INFO  [       ome.security.basic.CurrentDetails] (l.Server-9) Adding log:INSERT,class ome.model.meta.Session,209

2012-05-10 11:26:19,728 INFO  [                 org.perf4j.TimingLogger] (l.Server-3) start[1336645579657] time[71] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2012-05-10 11:26:19,729 INFO  [        ome.services.util.ServiceHandler] (l.Server-3)  Rslt:    (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2012-05-10 11:26:19,730 INFO  [ ome.services.blitz.fire.SessionManagerI] (l.Server-3) Created session ServiceFactoryI(session-b2e0bbad-60a5-4ee5-bcdf-062905037ca3/1a41a3c6-aebe-4a5b-a452-996cd5397b69) for user root (agent=Python service)
2012-05-10 11:26:19,736 INFO  [                 org.perf4j.TimingLogger] (l.Server-9) start[1336645579661] time[75] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2012-05-10 11:26:19,738 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Rslt:    (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2012-05-10 11:26:19,738 INFO  [ ome.services.blitz.fire.SessionManagerI] (l.Server-9) Created session ServiceFactoryI(session-8f0bd57a-d31f-4c07-9047-faed7d691801/d0eaaec3-8dc8-4419-80a5-c879f23f0b72) for user root (agent=Python service)
2012-05-10 11:26:19,742 INFO  [                      omero.cmd.SessionI] (l.Server-8) Added servant to adapter: d0eaaec3-8dc8-4419-80a5-c879f23f0b72/8f0bd57a-d31f-4c07-9047-faed7d691801omero.api.IConfig(omero.api._IConfigTie@ab3484a)
2012-05-10 11:26:19,742 INFO  [        ome.services.util.ServiceHandler] (l.Server-4)  Meth:    interface ome.api.IConfig.getConfigValue
2012-05-10 11:26:19,742 INFO  [        ome.services.util.ServiceHandler] (l.Server-4)  Args:    [omero.data.dir]
2012-05-10 11:26:19,762 INFO  [         ome.security.basic.EventHandler] (l.Server-4)  Auth:    user=0,group=0,event=62(User),sess=d0eaaec3-8dc8-4419-80a5-c879f23f0b72
2012-05-10 11:26:19,765 INFO  [                      omero.cmd.SessionI] (l.Server-6) Added servant to adapter: 1a41a3c6-aebe-4a5b-a452-996cd5397b69/b2e0bbad-60a5-4ee5-bcdf-062905037ca3omero.grid.SharedResources(omero.grid._SharedResourcesTie@a11c392)
2012-05-10 11:26:19,767 INFO  [                 org.perf4j.TimingLogger] (l.Server-4) start[1336645579742] time[25] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2012-05-10 11:26:19,767 INFO  [        ome.services.util.ServiceHandler] (l.Server-4)  Rslt:    /home/omero/OMERO.data
2012-05-10 11:26:19,769 INFO  [        ome.services.util.ServiceHandler] (l.Server-2)  Meth:    interface ome.api.IConfig.getDatabaseUuid
2012-05-10 11:26:19,769 INFO  [        ome.services.util.ServiceHandler] (l.Server-2)  Args:    ()
2012-05-10 11:26:19,792 INFO  [         ome.security.basic.EventHandler] (l.Server-2)  Auth:    user=0,group=0,event=63(User),sess=d0eaaec3-8dc8-4419-80a5-c879f23f0b72
2012-05-10 11:26:19,794 INFO  [                 org.perf4j.TimingLogger] (l.Server-2) start[1336645579769] time[25] tag[omero.call.success.ome.logic.ConfigImpl.getDatabaseUuid]
2012-05-10 11:26:19,794 INFO  [        ome.services.util.ServiceHandler] (l.Server-2)  Rslt:    de968e1e-1f1c-411d-921b-48206f5ea301
2012-05-10 11:26:19,808 INFO  [                      omero.cmd.SessionI] (l.Server-5) Added servant to adapter: d0eaaec3-8dc8-4419-80a5-c879f23f0b72/8f0bd57a-d31f-4c07-9047-faed7d691801omero.api.IQuery(omero.api._IQueryTie@b55c048)
2012-05-10 11:26:19,815 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Meth:    interface ome.api.IQuery.findByQuery
2012-05-10 11:26:19,815 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Args:    [select f from OriginalFile f where sha1 = :uuid, PARAMS:uuid=db95988d-2735-462e-81ae-2467b0a8e15d ]
2012-05-10 11:26:19,816 INFO  [         ome.security.basic.EventHandler] (l.Server-8)  Auth:    user=0,group=0,event=null(User),sess=d0eaaec3-8dc8-4419-80a5-c879f23f0b72
2012-05-10 11:26:19,822 INFO  [                 org.perf4j.TimingLogger] (l.Server-8) start[1336645579815] time[7] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2012-05-10 11:26:19,822 INFO  [        ome.services.util.ServiceHandler] (l.Server-8)  Rslt:    ome.model.core.OriginalFile:Id_51
2012-05-10 11:27:00,032 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-5) Performing requestHeartbeats
2012-05-10 11:30:00,018 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-2) Performing requestHeartbeats
2012-05-10 11:30:13,012 INFO  [            ome.services.blitz.fire.Ring] (2-thread-3) Checking cluster
2012-05-10 11:30:13,015 INFO  [        ome.services.blitz.fire.Registry] (2-thread-3) Found 1 cluster node(s) : [ClusterNode/8a7f8f70-67c6-4316-ad16-dd826eab6c10 -t:tcp -h 10.0.2.15 -p 33931]
2012-05-10 11:30:13,017 INFO  [            ome.services.blitz.fire.Ring] (2-thread-3) Got 1 cluster uuids : [8a7f8f70-67c6-4316-ad16-dd826eab6c10]
2012-05-10 11:30:13,017 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Executor.doWork -- ome.services.blitz.fire.Ring.getManagerList
2012-05-10 11:30:13,017 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Args:    [null, InternalSF@7793709]
2012-05-10 11:30:13,020 INFO  [         ome.security.basic.EventHandler] (2-thread-3)  Auth:    user=0,group=0,event=null(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:30:13,230 INFO  [                 org.perf4j.TimingLogger] (2-thread-3) start[1336645813017] time[213] tag[omero.call.success.ome.services.blitz.fire.Ring$2.doWork]
2012-05-10 11:30:13,230 INFO  [        ome.services.util.ServiceHandler] (2-thread-3)  Rslt:    (8a7f8f70-67c6-4316-ad16-dd826eab6c10)
2012-05-10 11:33:00,018 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-1) Performing requestHeartbeats
2012-05-10 11:36:00,018 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-3) Performing requestHeartbeats
2012-05-10 11:39:00,024 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-5) Performing requestHeartbeats
2012-05-10 11:39:34,519 INFO  [                ome.services.blitz.Entry] (      main) Calling close on context OMERO.blitz
2012-05-10 11:39:34,520 INFO  [.services.blitz.repo.AbstractRepositoryI] (      main) Releasing /home/omero/OMERO.server/./lib/scripts
2012-05-10 11:39:34,521 INFO  [.services.blitz.repo.AbstractRepositoryI] (      main) Releasing /home/omero/OMERO.data
2012-05-10 11:39:34,541 INFO  [        ome.services.blitz.fire.Registry] (      main) Removed ClusterNode/8a7f8f70-67c6-4316-ad16-dd826eab6c10 from registry
2012-05-10 11:39:34,542 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.executeUpdate - set closed = now()
2012-05-10 11:39:34,542 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@7793709]
2012-05-10 11:39:34,679 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=64(Internal),sess=8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:39:34,687 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646374542] time[145] tag[omero.call.success.ome.services.blitz.fire.Ring$3.doWork]
2012-05-10 11:39:34,687 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    2
2012-05-10 11:39:34,687 INFO  [            ome.services.blitz.fire.Ring] (      main) Removed 2 entries for 8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:39:34,687 INFO  [            ome.services.blitz.fire.Ring] (      main) Disconnected from OMERO.cluster
2012-05-10 11:39:34,688 INFO  [        ome.services.blitz.fire.Registry] (      main) Found 0 cluster node(s) : []
2012-05-10 11:39:34,688 INFO  [e.services.blitz.util.BlitzConfiguration] (      main) Shutting down Ice.Communicator
2012-05-10 11:39:34,693 INFO  [    ome.services.util.ServerVersionCheck] (      main) -------------------------------------------------
2012-05-10 11:39:34,693 INFO  [    ome.services.util.ServerVersionCheck] (      main) Stopping OMERO...
2012-05-10 11:39:34,693 INFO  [    ome.services.util.ServerVersionCheck] (      main) -------------------------------------------------
2012-05-10 11:39:34,698 INFO  [  ome.services.pixeldata.PixelDataThread] (      main) Shutting down PixelDataThread
2012-05-10 11:39:34,698 INFO  [    ome.services.fulltext.FullTextThread] (      main) Shutting down Full-Text Indexer
2012-05-10 11:39:34,700 INFO  [.services.scheduler.SchedulerFactoryBean] (      main) Shutting down Quartz Scheduler
2012-05-10 11:39:34,710 INFO  [ng.ShutdownSafeEhcacheManagerFactoryBean] (      main) Shutting down EHCache CacheManager
2012-05-10 11:39:34,710 INFO  [                ome.services.blitz.Entry] (      main) Finished shutdown.
2012-05-10 11:39:59,257 INFO  [                ome.services.blitz.Entry] (      main) Creating OMERO.blitz. Please wait...
2012-05-10 11:40:02,999 INFO  [ng.ShutdownSafeEhcacheManagerFactoryBean] (      main) Initializing EHCache CacheManager
2012-05-10 11:40:04,242 INFO  [          ome.services.util.DBPatchCheck] (      main) Verified database patch: OMERO4.3__0
2012-05-10 11:40:10,153 INFO  [  ome.services.fulltext.FullTextAnalyzer] (      main) Initialized FullTextAnalyzer
2012-05-10 11:40:17,916 INFO  [        ome.services.db.DatabaseIdentity] (      main) Using LSID format: urn:lsid:export.openmicroscopy.org:%s:de968e1e-1f1c-411d-921b-48206f5ea301_%s%s
2012-05-10 11:40:19,494 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646418012] time[1482] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:19,736 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646419498] time[238] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:19,962 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646419736] time[226] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:20,166 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646419962] time[204] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:20,381 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646420166] time[215] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:20,878 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646420382] time[496] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:21,073 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646420884] time[189] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:21,311 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646421080] time[231] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:21,503 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646421319] time[184] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:22,419 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646421504] time[915] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:22,558 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646422424] time[134] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:22,702 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646422561] time[141] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:22,836 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646422702] time[134] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:22,957 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646422836] time[121] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:23,085 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646422959] time[126] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:23,231 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646423085] time[146] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:23,512 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646423231] time[281] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:23,635 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646423518] time[117] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:23,761 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646423639] time[122] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:23,886 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646423762] time[124] tag[ome.io.nio.SimpleBackOff.256X256]
2012-05-10 11:40:23,901 INFO  [                ome.io.nio.PixelsService] (      main) PixelsService(path=/home/omero/OMERO.data, resolver=ome.services.OmeroFilePathResolver@137e216, backoff=ome.io.nio.SimpleBackOff(factor=144.6), sizes=ome.io.nio.ConfiguredTileSizes(w=256,h=256,W=3192,H=3192))
2012-05-10 11:40:24,231 INFO  [    ome.services.fulltext.FullTextThread] (      main) Initializing Full-Text Indexer
2012-05-10 11:40:24,245 INFO  [  ome.services.pixeldata.PixelDataThread] (      main) Initializing PixelDataThread (create events only)
2012-05-10 11:40:24,848 INFO  [    ome.services.util.ServerVersionCheck] (      main) -------------------------------------------------
2012-05-10 11:40:24,849 INFO  [    ome.services.util.ServerVersionCheck] (      main) OMERO Version: 4.3.3-1458-48edaf0-ice33-b2989 Ready.
2012-05-10 11:40:24,849 INFO  [    ome.services.util.ServerVersionCheck] (      main) -------------------------------------------------
2012-05-10 11:40:34,879 ERROR [                 ome.system.UpgradeCheck] (      main) Error reading from url: http://upgrade.openmicroscopy.org.uk?version=4.3.3-1458-48edaf0-ice33-b2989;os.name=Linux;os.arch=i386;os.version=2.6.32-5-686;java.runtime.version=1.6.0_26-b03;java.vm.vendor=Sun+Microsystems+Inc. "connect timed out"
2012-05-10 11:40:34,885 INFO  [    ome.tools.hibernate.ExtendedMetadata] (      main) Calculating ExtendedMetadata...
2012-05-10 11:40:34,957 INFO  [.services.scheduler.SchedulerFactoryBean] (      main) Starting Quartz Scheduler now
2012-05-10 11:40:34,962 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.util.NamespaceCheck.namespaceCheck
2012-05-10 11:40:34,962 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:35,415 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=101(Internal),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:35,539 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646434962] time[577] tag[omero.call.success.ome.services.util.NamespaceCheck$1.doWork]
2012-05-10 11:40:35,539 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    null
2012-05-10 11:40:35,668 INFO  [e.services.blitz.util.BlitzConfiguration] (      main) Initializing Ice.Communicator
2012-05-10 11:40:35,778 INFO  [            ome.services.blitz.fire.Ring] (      main) Checking cluster
2012-05-10 11:40:35,808 INFO  [        ome.services.blitz.fire.Registry] (      main) Found 0 cluster node(s) : []
2012-05-10 11:40:35,808 INFO  [            ome.services.blitz.fire.Ring] (      main) Got 0 cluster uuids : []
2012-05-10 11:40:35,809 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.getManagerList
2012-05-10 11:40:35,809 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:35,813 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=null(Internal),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:35,824 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646435809] time[15] tag[omero.call.success.ome.services.blitz.fire.Ring$2.doWork]
2012-05-10 11:40:35,824 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    (8a7f8f70-67c6-4316-ad16-dd826eab6c10)
2012-05-10 11:40:35,825 INFO  [            ome.services.blitz.fire.Ring] (      main) Purging node: 8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:40:36,101 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.executeUpdate - set closed = now()
2012-05-10 11:40:36,102 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:36,118 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=102(Internal),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:36,126 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646436102] time[24] tag[omero.call.success.ome.services.blitz.fire.Ring$3.doWork]
2012-05-10 11:40:36,126 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    0
2012-05-10 11:40:36,126 INFO  [            ome.services.blitz.fire.Ring] (      main) Removed 0 entries with value 8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:40:36,127 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.setManagerDown
2012-05-10 11:40:36,127 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:36,140 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=103(Internal),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:36,143 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646436127] time[16] tag[omero.call.success.ome.services.blitz.fire.Ring$4.doWork]
2012-05-10 11:40:36,144 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    1
2012-05-10 11:40:36,144 INFO  [            ome.services.blitz.fire.Ring] (      main) Removed manager: 8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:40:36,144 INFO  [            ome.services.blitz.fire.Ring] (      main) handleRingShutdown: 8a7f8f70-67c6-4316-ad16-dd826eab6c10
2012-05-10 11:40:36,144 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.blitz.fire.Ring.addManager
2012-05-10 11:40:36,144 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:36,164 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=104(Internal),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:36,170 INFO  [       ome.security.basic.CurrentDetails] (      main) Adding log:INSERT,class ome.model.meta.Node,101
2012-05-10 11:40:36,177 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646436144] time[33] tag[omero.call.success.ome.services.blitz.fire.Ring$5.doWork]
2012-05-10 11:40:36,177 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    ome.model.meta.Node:Id_101
2012-05-10 11:40:36,181 INFO  [        ome.services.blitz.fire.Registry] (      main) Added ClusterNode/8112e0ca-3c6d-4d99-a776-20c05f177165 to registry
2012-05-10 11:40:36,298 INFO  [.services.blitz.repo.AbstractRepositoryI] (      main) Initializing repository in /home/omero/OMERO.data
2012-05-10 11:40:36,316 INFO  [        ome.services.util.ServiceHandler] (      main)  Executor.doWork -- ome.services.scripts.ScriptRepoHelper.loadAll(true)
2012-05-10 11:40:36,317 INFO  [        ome.services.util.ServiceHandler] (      main)  Args:    [null, InternalSF@6468511]

2012-05-10 11:40:36,340 INFO  [         ome.security.basic.EventHandler] (      main)  Auth:    user=0,group=0,event=105(Internal),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:36,406 INFO  [                 org.perf4j.TimingLogger] (      main) start[1336646436317] time[89] tag[omero.call.success.ome.services.scripts.ScriptRepoHelper$5.doWork]
2012-05-10 11:40:36,406 INFO  [        ome.services.util.ServiceHandler] (      main)  Rslt:    (ome.model.core.OriginalFile:Id_1, ome.model.core.OriginalFile:Id_2, ome.model.core.OriginalFile:Id_3, ... 10 more)
2012-05-10 11:40:36,406 INFO  [.services.blitz.repo.AbstractRepositoryI] (      main) Initializing repository in /home/omero/OMERO.server/./lib/scripts
2012-05-10 11:40:36,459 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Executor.doWork -- ome.services.blitz.repo.ScriptRepositoryI.takeover
2012-05-10 11:40:36,459 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:36,462 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Executor.doWork -- ome.services.blitz.repo.LegacyRepositoryI.takeover
2012-05-10 11:40:36,462 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:36,482 INFO  [    ome.services.blitz.util.CheckAllJobs] (  Thread-8) Waiting 120 secs. for callbacks
2012-05-10 11:40:36,483 INFO  [                ome.services.blitz.Entry] (      main) OMERO.blitz now accepting connections.
2012-05-10 11:40:36,495 INFO  [         ome.security.basic.EventHandler] (2-thread-2)  Auth:    user=0,group=0,event=106(Internal),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:36,509 INFO  [.services.blitz.repo.AbstractRepositoryI] (2-thread-2) Opened repository scripts (uuid=ScriptRepo)
2012-05-10 11:40:36,523 INFO  [         ome.security.basic.EventHandler] (2-thread-1)  Auth:    user=0,group=0,event=107(Internal),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:36,530 INFO  [.services.blitz.repo.AbstractRepositoryI] (2-thread-1) Opened repository OMERO.data (uuid=db95988d-2735-462e-81ae-2467b0a8e15d)
2012-05-10 11:40:36,549 INFO  [        ome.services.blitz.fire.Registry] (2-thread-2) Updated InternalRepository-ScriptRepo in registry
2012-05-10 11:40:36,551 INFO  [        ome.services.blitz.fire.Registry] (2-thread-2) Updated PublicRepository-ScriptRepo in registry
2012-05-10 11:40:36,552 INFO  [        ome.services.blitz.fire.Registry] (2-thread-1) Updated InternalRepository-db95988d-2735-462e-81ae-2467b0a8e15d in registry
2012-05-10 11:40:36,555 INFO  [        ome.services.blitz.fire.Registry] (2-thread-1) Updated PublicRepository-db95988d-2735-462e-81ae-2467b0a8e15d in registry
2012-05-10 11:40:36,558 INFO  [.services.blitz.repo.AbstractRepositoryI] (2-thread-1) Repository now active
2012-05-10 11:40:36,558 INFO  [.services.blitz.repo.AbstractRepositoryI] (2-thread-2) Repository now active
2012-05-10 11:40:36,565 INFO  [                 org.perf4j.TimingLogger] (2-thread-1) start[1336646436462] time[103] tag[omero.call.success.ome.services.blitz.repo.AbstractRepositoryI$GetOrCreateRepo.doWork]
2012-05-10 11:40:36,565 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Rslt:    ome.model.core.OriginalFile:Id_51
2012-05-10 11:40:36,566 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Executor.doWork -- ome.services.blitz.repo.LegacyRepositoryI.getDescription(51)
2012-05-10 11:40:36,566 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:36,565 INFO  [                 org.perf4j.TimingLogger] (2-thread-2) start[1336646436459] time[106] tag[omero.call.success.ome.services.blitz.repo.AbstractRepositoryI$GetOrCreateRepo.doWork]
2012-05-10 11:40:36,566 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Rslt:    ome.model.core.OriginalFile:Id_52
2012-05-10 11:40:36,566 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Executor.doWork -- ome.services.blitz.repo.ScriptRepositoryI.getDescription(52)
2012-05-10 11:40:36,566 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:36,568 INFO  [         ome.security.basic.EventHandler] (2-thread-2)  Auth:    user=0,group=0,event=null(Internal),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:36,569 INFO  [         ome.security.basic.EventHandler] (2-thread-1)  Auth:    user=0,group=0,event=null(Internal),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:36,591 INFO  [                 org.perf4j.TimingLogger] (2-thread-1) start[1336646436566] time[25] tag[omero.call.success.ome.services.blitz.repo.AbstractRepositoryI$1.doWork]
2012-05-10 11:40:36,592 INFO  [        ome.services.util.ServiceHandler] (2-thread-1)  Rslt:    ome.model.core.OriginalFile:Id_51
2012-05-10 11:40:36,594 INFO  [                 org.perf4j.TimingLogger] (2-thread-2) start[1336646436566] time[28] tag[omero.call.success.ome.services.blitz.repo.AbstractRepositoryI$1.doWork]
2012-05-10 11:40:36,595 INFO  [        ome.services.util.ServiceHandler] (2-thread-2)  Rslt:    ome.model.core.OriginalFile:Id_52
2012-05-10 11:40:38,789 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2012-05-10 11:40:38,789 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:38,808 INFO  [         ome.security.basic.EventHandler] (l.Server-5)  Auth:    user=0,group=0,event=108(Sessions),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:38,835 INFO  [       ome.security.basic.CurrentDetails] (l.Server-5) Adding log:INSERT,class ome.model.meta.Session,361
2012-05-10 11:40:38,865 INFO  [                 org.perf4j.TimingLogger] (l.Server-5) start[1336646438789] time[76] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2012-05-10 11:40:38,865 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Rslt:    (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2012-05-10 11:40:38,877 INFO  [ ome.services.blitz.fire.SessionManagerI] (l.Server-5) Created session ServiceFactoryI(session-f5090abf-59c7-46ef-ab10-4bcaeadf1779/30fc5637-b4c7-42fd-85a6-336e42a4c09a) for user root (agent=Python service)
2012-05-10 11:40:38,890 INFO  [                      omero.cmd.SessionI] (l.Server-8) Added servant to adapter: 30fc5637-b4c7-42fd-85a6-336e42a4c09a/f5090abf-59c7-46ef-ab10-4bcaeadf1779omero.api.IConfig(omero.api._IConfigTie@1843c423)
2012-05-10 11:40:38,898 INFO  [        ome.services.util.ServiceHandler] (l.Server-1)  Meth:    interface ome.api.IConfig.getConfigValue
2012-05-10 11:40:38,898 INFO  [        ome.services.util.ServiceHandler] (l.Server-1)  Args:    [omero.data.dir]
2012-05-10 11:40:38,911 INFO  [         ome.security.basic.EventHandler] (l.Server-1)  Auth:    user=0,group=0,event=109(User),sess=30fc5637-b4c7-42fd-85a6-336e42a4c09a
2012-05-10 11:40:38,914 INFO  [                 org.perf4j.TimingLogger] (l.Server-1) start[1336646438898] time[16] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2012-05-10 11:40:38,914 INFO  [        ome.services.util.ServiceHandler] (l.Server-1)  Rslt:    /home/omero/OMERO.data
2012-05-10 11:40:38,916 INFO  [e.services.sessions.SessionContext$Count] (l.Server-3) -Reference count: 30fc5637-b4c7-42fd-85a6-336e42a4c09a=0
2012-05-10 11:40:38,916 INFO  [                      omero.cmd.SessionI] (l.Server-3) doDestroy(ServiceFactoryI(session-f5090abf-59c7-46ef-ab10-4bcaeadf1779/30fc5637-b4c7-42fd-85a6-336e42a4c09a))
2012-05-10 11:40:38,917 INFO  [                      omero.cmd.SessionI] (l.Server-3) Unregistered servant:30fc5637-b4c7-42fd-85a6-336e42a4c09a/f5090abf-59c7-46ef-ab10-4bcaeadf1779omero.api.IConfig(omero.api._IConfigTie@1843c423)
2012-05-10 11:40:38,917 INFO  [                      omero.cmd.SessionI] (l.Server-3) Removed servant from adapter: f5090abf-59c7-46ef-ab10-4bcaeadf1779omero.api.IConfig
2012-05-10 11:40:38,917 INFO  [ome.services.sessions.SessionManagerImpl] (l.Server-3) closeSession called and no more references: 30fc5637-b4c7-42fd-85a6-336e42a4c09a
2012-05-10 11:40:38,917 INFO  [ome.services.sessions.state.SessionCache] (l.Server-3) Destroying session 30fc5637-b4c7-42fd-85a6-336e42a4c09a due to : Remove session called
2012-05-10 11:40:38,917 INFO  [                 org.perf4j.TimingLogger] (l.Server-3) start[1336646438867] time[50] tag[omero.session]
2012-05-10 11:40:38,920 INFO  [ ome.services.blitz.fire.SessionManagerI] (l.Server-3) Reaping 1 clients for 30fc5637-b4c7-42fd-85a6-336e42a4c09a
2012-05-10 11:40:45,787 INFO  [        ome.services.util.ServiceHandler] (l.Server-6)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2012-05-10 11:40:45,787 INFO  [        ome.services.util.ServiceHandler] (l.Server-6)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:45,789 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Executor.doWork -- ome.services.sessions.SessionManagerImpl.createSession
2012-05-10 11:40:45,789 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Args:    [null, InternalSF@6468511]
2012-05-10 11:40:45,810 INFO  [         ome.security.basic.EventHandler] (l.Server-9)  Auth:    user=0,group=0,event=111(Sessions),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:45,811 INFO  [         ome.security.basic.EventHandler] (l.Server-6)  Auth:    user=0,group=0,event=110(Sessions),sess=8112e0ca-3c6d-4d99-a776-20c05f177165
2012-05-10 11:40:45,830 INFO  [       ome.security.basic.CurrentDetails] (l.Server-9) Adding log:INSERT,class ome.model.meta.Session,362

2012-05-10 11:40:45,831 INFO  [       ome.security.basic.CurrentDetails] (l.Server-6) Adding log:INSERT,class ome.model.meta.Session,363
2012-05-10 11:40:45,854 INFO  [                 org.perf4j.TimingLogger] (l.Server-9) start[1336646445789] time[65] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2012-05-10 11:40:45,854 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Rslt:    (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2012-05-10 11:40:45,854 INFO  [                 org.perf4j.TimingLogger] (l.Server-6) start[1336646445788] time[66] tag[omero.call.success.ome.services.sessions.SessionManagerImpl$2.doWork]
2012-05-10 11:40:45,854 INFO  [        ome.services.util.ServiceHandler] (l.Server-6)  Rslt:    (ome.model.meta.Experimenter:Id_0, ome.model.meta.ExperimenterGroup:Id_0, (0, 1), ... 4 more)
2012-05-10 11:40:45,855 INFO  [ ome.services.blitz.fire.SessionManagerI] (l.Server-6) Created session ServiceFactoryI(session-beb8682a-b475-4e8b-bc7c-c8b0240097e5/aa5541db-d82e-4dd4-a402-4536df0642e4) for user root (agent=Python service)
2012-05-10 11:40:45,856 INFO  [ ome.services.blitz.fire.SessionManagerI] (l.Server-9) Created session ServiceFactoryI(session-dcf01847-828e-43e5-bd71-5aa39f3b10c5/7f9b5138-e17c-4e07-ae80-7feac9ed86e0) for user root (agent=Python service)
2012-05-10 11:40:45,868 INFO  [    ome.services.blitz.util.CheckAllJobs] (l.Server-7) Received 0 job(s)
2012-05-10 11:40:45,875 INFO  [                      omero.cmd.SessionI] (l.Server-5) Added servant to adapter: 7f9b5138-e17c-4e07-ae80-7feac9ed86e0/dcf01847-828e-43e5-bd71-5aa39f3b10c5omero.api.IConfig(omero.api._IConfigTie@17abffd9)
2012-05-10 11:40:45,876 INFO  [        ome.services.util.ServiceHandler] (l.Server-2)  Meth:    interface ome.api.IConfig.getConfigValue
2012-05-10 11:40:45,876 INFO  [        ome.services.util.ServiceHandler] (l.Server-2)  Args:    [omero.data.dir]
2012-05-10 11:40:45,895 INFO  [                      omero.cmd.SessionI] (l.Server-4) Added servant to adapter: aa5541db-d82e-4dd4-a402-4536df0642e4/beb8682a-b475-4e8b-bc7c-c8b0240097e5omero.grid.SharedResources(omero.grid._SharedResourcesTie@17f4f7ef)
2012-05-10 11:40:45,895 INFO  [         ome.security.basic.EventHandler] (l.Server-2)  Auth:    user=0,group=0,event=112(User),sess=7f9b5138-e17c-4e07-ae80-7feac9ed86e0
2012-05-10 11:40:45,898 INFO  [                 org.perf4j.TimingLogger] (l.Server-2) start[1336646445876] time[22] tag[omero.call.success.ome.logic.ConfigImpl.getConfigValue]
2012-05-10 11:40:45,898 INFO  [        ome.services.util.ServiceHandler] (l.Server-2)  Rslt:    /home/omero/OMERO.data
2012-05-10 11:40:45,899 INFO  [        ome.services.util.ServiceHandler] (l.Server-0)  Meth:    interface ome.api.IConfig.getDatabaseUuid
2012-05-10 11:40:45,899 INFO  [        ome.services.util.ServiceHandler] (l.Server-0)  Args:    ()
2012-05-10 11:40:45,918 INFO  [         ome.security.basic.EventHandler] (l.Server-0)  Auth:    user=0,group=0,event=113(User),sess=7f9b5138-e17c-4e07-ae80-7feac9ed86e0
2012-05-10 11:40:45,921 INFO  [                 org.perf4j.TimingLogger] (l.Server-0) start[1336646445899] time[22] tag[omero.call.success.ome.logic.ConfigImpl.getDatabaseUuid]
2012-05-10 11:40:45,921 INFO  [        ome.services.util.ServiceHandler] (l.Server-0)  Rslt:    de968e1e-1f1c-411d-921b-48206f5ea301
2012-05-10 11:40:45,934 INFO  [                      omero.cmd.SessionI] (l.Server-9) Added servant to adapter: 7f9b5138-e17c-4e07-ae80-7feac9ed86e0/dcf01847-828e-43e5-bd71-5aa39f3b10c5omero.api.IQuery(omero.api._IQueryTie@197cc04e)
2012-05-10 11:40:45,940 INFO  [        ome.services.util.ServiceHandler] (l.Server-7)  Meth:    interface ome.api.IQuery.findByQuery
2012-05-10 11:40:45,940 INFO  [        ome.services.util.ServiceHandler] (l.Server-7)  Args:    [select f from OriginalFile f where sha1 = :uuid, PARAMS:uuid=db95988d-2735-462e-81ae-2467b0a8e15d ]
2012-05-10 11:40:45,941 INFO  [         ome.security.basic.EventHandler] (l.Server-7)  Auth:    user=0,group=0,event=null(User),sess=7f9b5138-e17c-4e07-ae80-7feac9ed86e0
2012-05-10 11:40:45,947 INFO  [                 org.perf4j.TimingLogger] (l.Server-7) start[1336646445940] time[7] tag[omero.call.success.ome.logic.QueryImpl.findByQuery]
2012-05-10 11:40:45,947 INFO  [        ome.services.util.ServiceHandler] (l.Server-7)  Rslt:    ome.model.core.OriginalFile:Id_51
2012-05-10 11:42:00,029 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-5) Performing requestHeartbeats
2012-05-10 11:45:00,023 INFO  [ ome.services.blitz.fire.SessionManagerI] (2-thread-4) Performing requestHeartbeats


[ckm]

This looks to be an issue with service ordering in the vm initscripts. I imported the same vm and postgres starts fine, has the schema loaded and the correct network settings. However omero.server is started before postgres gets fully initialized. When I restarted omero with no additional changes it looks better.

Login to your vm over ssh (or console) as the 'omero' user.

Code: Select all

$ cd OMERO.server
$ bin/omero admin stop
# this will clear the logs
$ for x in var/log/*.{log,err,out}; do : > $x ;done
$ bin/omero admin start
# show diagnostics
$ bin/omero admin diagnostics