Task #12321 (closed)
Opened 10 years ago
Closed 9 years ago
Bug: OMERO.tables close() doesn't properly release files on Windows
Reported by: | spli | Owned by: | spli |
---|---|---|---|
Priority: | major | Milestone: | 5.1.0-m4 |
Component: | General | Version: | 5.0.1 |
Keywords: | n.a. | Cc: | python-team@…, jamoore |
Resources: | n.a. | Referenced By: | n.a. |
References: | n.a. | Remaining Time: | n.a. |
Sprint: | n.a. |
Description
Windows 7, 64 bit, Ice 3.5, Python 2.7.6, Java 1.7.55
OMERO.server-5.0.2-rc1-73-71bbbc7-ice35-b309
Note I was running omero shell and connecting remotely.
In [41]: t=session.sharedResources().newTable(0,'test.h5') In [42]: t.getOriginalFile().id Out[42]: object #0 (::omero::RLong) { _val = 164 } In [43]: c=omero.grid.LongColumn('lc','lc 1',[]) In [44]: t.initialize([c]) In [45]: t.getN t.getNumberOfRows t.getNumberOfRows_async In [45]: t.getNumberOfRows() Out[45]: 0L In [46]: t.close() In [47]: t=session.sharedResources().openTable(omero.model.OriginalFileI(164)) In [48]: t In [49]: t=session.sharedResources().openTable(omero.model.OriginalFileI(164)) In [50]: t In [51]:
Tables-0.log
2014-05-26 07:25:31,032 INFO [ omero.remote] (Dummy-5 ) Meth: TablesI.getTable 2014-05-26 07:25:31,062 INFO [ omero.tables.TablesI] (Dummy-5 ) getTable: 164 {'omero.session.uuid': '413631de-baa2-4882-81a4-dc3b143a07c1', 'omero.client.uuid': '639050a0-2a74-4cef-9b99-81d4682352db'} 2014-05-26 07:25:31,109 INFO [ omero.tables.HdfStorage] (Dummy-5 ) Size: 0 - Attaching Table-15b779a4-c289-4e34-83d0-4d49ffb2e1a5 to C:\OMERO\Files\164 2014-05-26 07:25:31,125 INFO [ omero.remote] (Dummy-5 ) Rslt: 15b779a4-c289-4e34-83d0-4d49ffb2e1a5 -t -e 1.1 @ Tables-0.TablesAdapter 2014-05-26 07:25:34,516 INFO [ omero.remote] (Dummy-5 ) Meth: TableI.getOriginalFile 2014-05-26 07:25:34,516 INFO [ omero.tables.TableI] (Dummy-5 ) Table-15b779a4-c289-4e34-83d0-4d49ffb2e1a5.getOriginalFile() => id=164 2014-05-26 07:25:34,516 INFO [ omero.remote] (Dummy-5 ) Rslt: object #0 (::omero::model::OriginalFile) { _id = object #1 (::omero::RLong) { _val = 164 } _deta 2014-05-26 07:25:49,750 INFO [ omero.remote] (Dummy-5 ) Meth: TableI.initialize 2014-05-26 07:25:49,812 INFO [ omero.tables.TableI] (Dummy-5 ) Initialized Table-15b779a4-c289-4e34-83d0-4d49ffb2e1a5 with 1 col(s) 2014-05-26 07:25:49,828 INFO [ omero.remote] (Dummy-5 ) Rslt: None 2014-05-26 07:25:55,046 INFO [ omero.remote] (Dummy-5 ) Meth: TableI.getNumberOfRows 2014-05-26 07:25:55,046 INFO [ omero.tables.TableI] (Dummy-5 ) Table-15b779a4-c289-4e34-83d0-4d49ffb2e1a5.getNumberOfRows() => 0 2014-05-26 07:25:55,046 INFO [ omero.remote] (Dummy-5 ) Rslt: 0 2014-05-26 07:25:57,032 INFO [ omero.remote] (Dummy-5 ) Meth: TableI.close 2014-05-26 07:25:57,032 INFO [ omero.tables.HdfStorage] (Dummy-5 ) Size: 1 - Detaching Table-15b779a4-c289-4e34-83d0-4d49ffb2e1a5 from C:\OMERO\Files\164 2014-05-26 07:25:57,032 INFO [ omero.tables.HdfStorage] (Dummy-5 ) Cleaning storage: C:\OMERO\Files\164 2014-05-26 07:25:57,032 INFO [ omero.tables.TableI] (Dummy-5 ) Closed Table-15b779a4-c289-4e34-83d0-4d49ffb2e1a5 2014-05-26 07:25:57,250 INFO [ omero.tables.TableI] (Dummy-5 ) Updated file object 164 to hash=None (6000 bytes) 2014-05-26 07:25:57,250 INFO [ omero.remote] (Dummy-5 ) Rslt: None 2014-05-26 07:26:08,484 INFO [ omero.remote] (Dummy-5 ) Meth: TablesI.getTable 2014-05-26 07:26:08,484 INFO [ omero.tables.TablesI] (Dummy-5 ) getTable: 164 {'omero.session.uuid': '413631de-baa2-4882-81a4-dc3b143a07c1', 'omero.client.uuid': '639050a0-2a74-4cef-9b99-81d4682352db'} 2014-05-26 07:26:08,532 ERROR [ omero.tables.HdfStorage] (Dummy-5 ) HDFStorage initialized with bad path: C:\OMERO\Files\164 2014-05-26 07:26:08,532 INFO [ omero.remote] (Dummy-5 ) Excp: exception ::omero::ValidationException { serverStackTrace = None serverExceptionClass = None message = HDFSt 2014-05-26 07:34:42,641 INFO [ omero.remote] (Dummy-6 ) Meth: TablesI.getTable 2014-05-26 07:34:42,671 INFO [ omero.tables.TablesI] (Dummy-6 ) getTable: 164 {'omero.session.uuid': '413631de-baa2-4882-81a4-dc3b143a07c1', 'omero.client.uuid': '639050a0-2a74-4cef-9b99-81d4682352db'} 2014-05-26 07:34:42,687 INFO [ omero.remote] (Dummy-6 ) Excp: exception ::omero::LockTimeout { serverStackTrace = None serverExceptionClass = None message = Path already
C:\OMERO.server-5.0.2-rc1-73-71bbbc7-ice35-b309>python -c "import tables; print tables.__version__" 3.1.1
Change History (9)
comment:1 Changed 10 years ago by jamoore
- Milestone changed from Unscheduled to 5.0.3
- Summary changed from OMERO.tables close() doesn't properly release files on Windows to Bug: OMERO.tables close() doesn't properly release files on Windows
comment:2 Changed 9 years ago by spli
comment:3 Changed 9 years ago by jamoore
Simon: worth passing to you for the moment or push?
comment:4 Changed 9 years ago by spli
- Owner set to spli
comment:5 Changed 9 years ago by spli
- Cc python-team@… added; bpindelski spli khgillen removed
- Status changed from new to accepted
comment:6 Changed 9 years ago by spli
After adding a bit more logging, it appears something takes an exclusive lock on the file
res.openTable(omero.model.OriginalFileI(651))
2015-02-03 15:53:22,082 INFO [ omero.util.Server] (MainThread) Waiting 10000 ms on startup 2015-02-03 15:53:32,082 INFO [ omero.util.Server] (MainThread) Starting 2015-02-03 15:53:32,082 INFO [ omero.util.Server] (MainThread) Loaded dependency numpy (1.8.1) 2015-02-03 15:53:32,082 INFO [ omero.util.Server] (MainThread) Loaded dependency tables (3.1.1, hdf=1.8.11) 2015-02-03 15:53:32,088 INFO [ omero.util.Resources] (Thread-2 ) Starting 2015-02-03 15:53:33,276 INFO [ omero.util.Server] (MainThread) Entering main loop 2015-02-03 15:54:32,002 INFO [ omero.remote] (Dummy-3 ) Meth: TablesI.getTable 2015-02-03 15:54:32,003 INFO [ omero.tables.TablesI] (Dummy-3 ) getTable: 651 {'omero.session.uuid': 'f085cb5e-26b1-46ca-bbef-93826bcb338f', 'omero.client.uuid': '15bf7876-3d60-40a2-a93c-29406058ff8a'} 2015-02-03 15:54:32,010 INFO [ omero.tables.HdfList] (Dummy-3 ) addOrThrow c:\repositories\OMERO-5.1-merge-deploy-win\Files\651 <omero.tables.HdfStorage object at 0x0000000008D2BEB8> 2015-02-03 15:54:32,012 INFO [ omero.tables.HdfStorage] (Dummy-3 ) openfile c:\repositories\OMERO-5.1-merge-deploy-win\Files\651 a 2015-02-03 15:54:32,015 WARNI [ stderr] (Dummy-3 ) C:\jenkins\workspace\OMERO-5.1-merge-deploy-win\OMERO.server-5.1.0-m3-910-704dd72-ice34-b399\lib\python\omero\tables.py:241: DeprecationWarning: openFile() is pending deprecation, use open_file() instead. You may use the pt2to3 tool to update your source code. rootUEP="/") 2015-02-03 15:54:32,019 ERROR [ omero.tables.HdfStorage] (Dummy-3 ) HDFStorage initialized with bad path: c:\repositories\OMERO-5.1-merge-deploy-win\Files\651 HDF5 error back trace File "..\..\hdf5-1.8.11\src\H5F.c", line 1582, in H5Fopen unable to open file File "..\..\hdf5-1.8.11\src\H5F.c", line 1373, in H5F_open unable to read superblock File "..\..\hdf5-1.8.11\src\H5Fsuper.c", line 334, in H5F_super_read unable to find file signature File "..\..\hdf5-1.8.11\src\H5Fsuper.c", line 144, in H5F_locate_signature unable to read file signature File "..\..\hdf5-1.8.11\src\H5FDint.c", line 142, in H5FD_read driver read request failed File "..\..\hdf5-1.8.11\src\H5FDsec2.c", line 725, in H5FD_sec2_read file read failed: time = Tue Feb 03 15:54:32 2015 , filename = 'c:\repositories\OMERO-5.1-merge-deploy-win\Files\651', file descriptor = 5, errno = 13, error message = 'Permission denied', buf = 000000000C63A490, total read size = 8, bytes this sub-read = 8, bytes actually read = 18446744073709551615, offset = 0 End of HDF5 error back trace Unable to open/create file 'c:\repositories\OMERO-5.1-merge-deploy-win\Files\651' 2015-02-03 15:54:32,019 INFO [ omero.remote] (Dummy-3 ) Excp: exception ::omero::ValidationException { serverStackTrace = None serverExceptionClass = None message = HDFSt
Though according to c:\SysinternalsSuite?\handle.exe the Tables python process has it open... so maybe something else in that process is alaos attempting to open it? Though adding logging to HdfStorage?.openfile and HdfList?.addOrThrow shows them only being called once.
------------------------------------------------------------------------------ python.exe pid: 7320 NT AUTHORITY\SYSTEM C: File (RW-) C:\jenkins\workspace\OMERO-5.1-merge-deploy-win\OMERO.server-5.1.0-m3-910-704dd72-ice34-b399 1C: File (RW-) C:\Windows\winsxs\amd64_microsoft.vc90.crt_1fc8b3b9a1e18e3b_9.0.30729.4148_none_08e3747fa83e48bc 20: File (RW-) C:\Windows\winsxs\amd64_microsoft.vc90.crt_1fc8b3b9a1e18e3b_9.0.30729.4148_none_08e3747fa83e48bc 7C: File (R-D) C:\Windows\System32\en-US\KernelBase.dll.mui 9C: File (RW-) C:\Windows\winsxs\amd64_microsoft.vc90.crt_1fc8b3b9a1e18e3b_9.0.30729.4148_none_08e3747fa83e48bc A0: File (RW-) C:\Windows\winsxs\amd64_microsoft.vc90.crt_1fc8b3b9a1e18e3b_9.0.30729.4148_none_08e3747fa83e48bc A4: File (RW-) C:\Windows\winsxs\amd64_microsoft.vc90.crt_1fc8b3b9a1e18e3b_9.0.30729.4148_none_08e3747fa83e48bc A8: File (RW-) C:\Windows\winsxs\amd64_microsoft.vc90.crt_1fc8b3b9a1e18e3b_9.0.30729.4148_none_08e3747fa83e48bc AC: File (RW-) C:\Windows\winsxs\amd64_microsoft.vc90.crt_1fc8b3b9a1e18e3b_9.0.30729.4148_none_08e3747fa83e48bc CC: File (RW-) C:\Windows\winsxs\amd64_microsoft.vc90.crt_1fc8b3b9a1e18e3b_9.0.30729.4148_none_08e3747fa83e48bc 2E0: File (RW-) C:\repositories\OMERO-5.1-merge-deploy-win\Files\651 2F4: File (RW-) C:\jenkins\workspace\OMERO-5.1-merge-deploy-win\OMERO.server-5.1.0-m3-910-704dd72-ice34-b399\var\log\Tables-0.log ------------------------------------------------------------------------------
comment:7 Changed 9 years ago by spli
diff --git a/components/tools/OmeroPy/src/omero/tables.py b/components/tools/OmeroPy/src/omero/tables.py index ef7ed57..4291131 100644 --- a/components/tools/OmeroPy/src/omero/tables.py +++ b/components/tools/OmeroPy/src/omero/tables.py @@ -113,8 +113,17 @@ class HdfList(object): self.__paths = {} self.__locks = {} + def testReadable(self, hdfpath, prefix=''): + try: + with open(str(hdfpath)) as f: + self.logger.info('self.testReadable [%s]: %d', prefix, len(f.read())) + except Exception as e: + self.logger.error('self.testReadable [%s]: FAILED: %s', prefix, e) + @locked def addOrThrow(self, hdfpath, hdfstorage): + self.logger.info('addOrThrow %s %s', hdfpath, hdfstorage) + self.testReadable(hdfpath, '1') if hdfpath in self.__locks: raise omero.LockTimeout( @@ -127,9 +136,13 @@ class HdfList(object): lock = None try: + self.testReadable(hdfpath, '2') lock = open(hdfpath, "a+") + self.testReadable(hdfpath, '3') portalocker.lock(lock, portalocker.LOCK_NB | portalocker.LOCK_EX) + self.testReadable(hdfpath, '4') self.__locks[hdfpath] = lock + self.testReadable(hdfpath, '5') except portalocker.LockException: if lock: lock.close() @@ -141,6 +154,7 @@ class HdfList(object): lock.close() raise + self.testReadable(hdfpath, '6') hdffile = hdfstorage.openfile("a") fileno = hdffile.fileno() if fileno in self.__filenos.keys(): @@ -231,6 +245,7 @@ class HdfStorage(object): return self.__hdf_path.size def openfile(self, mode): + self.logger.info('openfile %s %s', self.__hdf_path, mode) try: if self.__hdf_path.exists() and self.__hdf_path.size == 0: mode = "w"
2015-02-03 16:12:23,851 INFO [ omero.util.Server] (MainThread) ******************************************************************************** 2015-02-03 16:12:23,851 INFO [ omero.util.Server] (MainThread) Waiting 10000 ms on startup 2015-02-03 16:12:33,851 INFO [ omero.util.Server] (MainThread) Starting 2015-02-03 16:12:33,852 INFO [ omero.util.Server] (MainThread) Loaded dependency numpy (1.8.1) 2015-02-03 16:12:33,852 INFO [ omero.util.Server] (MainThread) Loaded dependency tables (3.1.1, hdf=1.8.11) 2015-02-03 16:12:33,858 INFO [ omero.util.Resources] (Thread-2 ) Starting 2015-02-03 16:12:34,381 INFO [ omero.util.Server] (MainThread) Entering main loop 2015-02-03 16:12:48,298 INFO [ omero.remote] (Dummy-3 ) Meth: TablesI.getTable 2015-02-03 16:12:48,299 INFO [ omero.tables.TablesI] (Dummy-3 ) getTable: 651 {'omero.session.uuid': 'f085cb5e-26b1-46ca-bbef-93826bcb338f', 'omero.client.uuid': '15bf7876-3d60-40a2-a93c-29406058ff8a'} 2015-02-03 16:12:48,308 INFO [ omero.tables.HdfList] (Dummy-3 ) addOrThrow c:\repositories\OMERO-5.1-merge-deploy-win\Files\651 <omero.tables.HdfStorage object at 0x0000000008D42F60> 2015-02-03 16:12:48,315 INFO [ omero.tables.HdfList] (Dummy-3 ) self.testReadable [1]: 5 2015-02-03 16:12:48,315 INFO [ omero.tables.HdfList] (Dummy-3 ) self.testReadable [2]: 5 2015-02-03 16:12:48,316 INFO [ omero.tables.HdfList] (Dummy-3 ) self.testReadable [3]: 5 2015-02-03 16:12:48,316 ERROR [ omero.tables.HdfList] (Dummy-3 ) self.testReadable [4]: FAILED: [Errno 13] Permission denied 2015-02-03 16:12:48,318 ERROR [ omero.tables.HdfList] (Dummy-3 ) self.testReadable [5]: FAILED: [Errno 13] Permission denied 2015-02-03 16:12:48,319 ERROR [ omero.tables.HdfList] (Dummy-3 ) self.testReadable [6]: FAILED: [Errno 13] Permission denied 2015-02-03 16:12:48,319 INFO [ omero.tables.HdfStorage] (Dummy-3 ) openfile c:\repositories\OMERO-5.1-merge-deploy-win\Files\651 a 2015-02-03 16:12:48,322 WARNI [ stderr] (Dummy-3 ) C:\jenkins\workspace\OMERO-5.1-merge-deploy-win\OMERO.server-5.1.0-m3-910-704dd72-ice34-b399\lib\python\omero\tables.py:254: DeprecationWarning: openFile() is pending deprecation, use open_file() instead. You may use the pt2to3 tool to update your source code. rootUEP="/") 2015-02-03 16:12:48,325 ERROR [ omero.tables.HdfStorage] (Dummy-3 ) HDFStorage initialized with bad path: c:\repositories\OMERO-5.1-merge-deploy-win\Files\651 HDF5 error back trace File "..\..\hdf5-1.8.11\src\H5F.c", line 1582, in H5Fopen unable to open file File "..\..\hdf5-1.8.11\src\H5F.c", line 1373, in H5F_open unable to read superblock File "..\..\hdf5-1.8.11\src\H5Fsuper.c", line 334, in H5F_super_read unable to find file signature File "..\..\hdf5-1.8.11\src\H5Fsuper.c", line 144, in H5F_locate_signature unable to read file signature File "..\..\hdf5-1.8.11\src\H5FDint.c", line 142, in H5FD_read driver read request failed File "..\..\hdf5-1.8.11\src\H5FDsec2.c", line 725, in H5FD_sec2_read file read failed: time = Tue Feb 03 16:12:48 2015 , filename = 'c:\repositories\OMERO-5.1-merge-deploy-win\Files\651', file descriptor = 5, errno = 13, error message = 'Permission denied', buf = 000000000C6AA490, total read size = 8, bytes this sub-read = 8, bytes actually read = 18446744073709551615, offset = 0 End of HDF5 error back trace Unable to open/create file 'c:\repositories\OMERO-5.1-merge-deploy-win\Files\651' 2015-02-03 16:12:48,325 INFO [ omero.remote] (Dummy-3 ) Excp: exception ::omero::ValidationException { serverStackTrace = None serverExceptionClass = None message = HDFSt
Portalocker is takes an exclusive lock on the file... and prevents tables.open_file from opening it. Obviously portalocker.py - Cross-platform (posix/nt) API for flock-style file locking. isn't entirely accurate.
comment:9 Changed 9 years ago by spli
- Resolution set to fixed
- Status changed from accepted to closed
Also broken with current 5.1-merge on Hake (32 bit, Python 2.6, tables 3.1.1)