Notice: In order to edit this ticket you need to be either: a Product Owner, The owner or the reporter of the ticket, or, in case of a Task not yet assigned, a team_member"

Task #12321 (closed)

Opened 5 years ago

Closed 4 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 5 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 5 years ago by spli

Also broken with current 5.1-merge on Hake (32 bit, Python 2.6, tables 3.1.1)

comment:3 Changed 5 years ago by jamoore

Simon: worth passing to you for the moment or push?

comment:4 Changed 5 years ago by spli

  • Owner set to spli

comment:5 Changed 5 years ago by spli

  • Cc python-team@… added; bpindelski spli khgillen removed
  • Status changed from new to accepted

comment:6 Changed 5 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 5 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 4 years ago by spli

  • Resolution set to fixed
  • Status changed from accepted to closed
Note: See TracTickets for help on using tickets. You may also have a look at Agilo extensions to the ticket.

1.3.13-PRO © 2008-2011 Agilo Software all rights reserved (this page was served in: 0.109224 sec.)

© 2000-2014 University of Dundee & Open Microscopy Environment. Creative Commons Attribution 3.0 Unported License
OME source code is available under the GNU General public license or through commercial license from Glencoe Software

We're Hiring!