Open Microscopy Environment

Posted: **Wed May 09, 2012 1:55 pm**

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?

Posted: **Thu May 10, 2012 7:23 am**

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

Posted: **Thu May 10, 2012 9:00 am**

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

Posted: **Thu May 10, 2012 9:03 am**

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

Posted: **Tue May 15, 2012 10:09 pm**

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

Open Microscopy Environment

VM omero having postrgres problems

VM omero having postrgres problems

Re: VM omero having postrgres problems

Re: VM omero having postrgres problems

Re: VM omero having postrgres problems

Re: VM omero having postrgres problems