tables: call delete callback #152

joshmoore · 2019-12-18T07:54:30Z

In testing the table closing logic for 5.5.1, I set up a tight loop to
create, delete, and close a table. At 10000 servants it failed because
the callbacks were not being cleaned up. This adds a try/finally block
in order to do so. Two things to note:

Making use of client.submit() is not possible since we only have a
ServiceFactoryPrx
I don't believe the nulling of the file_obj was appropriate since
that's part of the close logic

transferred from: ome/openmicroscopy#6082

In testing the table closing logic for 5.5.1, I set up a tight loop to create, delete, and close a table. At 10000 servants it failed because the callbacks were not being cleaned up. This adds a try/finally block in order to do so. Two things to note: 1. Making use of client.submit() is not possible since we only have a ServiceFactoryPrx 2. I don't believe the nulling of the file_obj was appropriate since that's part of the close logic transferred from: ome/openmicroscopy#6082

will-moore · 2020-01-20T22:53:39Z

Using this test script against my local server, I hit the same exception at the same point without and with this PR:

testtables.py


from omero.gateway import BlitzGateway
from random import random
import omero

conn = BlitzGateway('user', 'password', port=4064, host='localhost')
conn.connect()

for i in range(15000):
    print(i)
    table_name = "TablesDemo:%s" % str(random())
    col1 = omero.grid.LongColumn('Uid', 'testLong', [])
    col2 = omero.grid.StringColumn('MyStringColumnInit', '', 64, [])
    columns = [col1, col2]

    resources = conn.c.sf.sharedResources()
    repository_id = resources.repositories().descriptions[0].getId().getValue()
    table = resources.newTable(repository_id, table_name)
    table.initialize(columns)

    ids = [1, 2, 3, 4, 5, 6, 7, 8, 9, 10]
    strings = ["one", "two", "three", "four", "five",
            "six", "seven", "eight", "nine", "ten"]
    data1 = omero.grid.LongColumn('Uid', 'test Long', ids)
    data2 = omero.grid.StringColumn('MyStringColumn', '', 64, strings)
    data = [data1, data2]
    table.addData(data)
    orig_file = table.getOriginalFile()
    table.close()           # when we are done, close.

    open_table = resources.openTable(orig_file)
    open_table.delete()

print('done')
conn.close()

Exception

...
3331
3332
Traceback (most recent call last):
  File "tabletest.py", line 32, in <module>
    open_table.delete()
  File "/Users/wmoore/Desktop/OMEROPY/omero-py/target/omero_Tables_ice.py", line 1401, in delete
    return _M_omero.grid.Table._op_delete.invoke(self, ((), _ctx))
omero.InternalException: exception ::omero::InternalException
{
    serverStackTrace = Traceback (most recent call last):
  File "/Users/wmoore/Desktop/OMEROPY/omero-py/target/omero/util/decorators.py", line 69, in exc_handler
    rv = func(*args, **kwargs)
  File "/Users/wmoore/Desktop/OMEROPY/omero-py/target/omero/util/decorators.py", line 29, in handler
    return func(*args, **kwargs)
  File "/Users/wmoore/Desktop/OMEROPY/omero-py/target/omero/tables.py", line 312, in delete
    handle = self.factory.submit(dc)
  File "/Users/wmoore/Desktop/OMEROPY/omero-py/target/omero_cmd_API_ice.py", line 951, in submit
    return _M_omero.cmd.Session._op_submit.invoke(self, ((req, ), _ctx))
Ice.UnknownUserException: exception ::Ice::UnknownUserException
{
    unknown = omero::OverUsageException
omero.OverUsageException
    serverStackTrace = "ome.conditions.OverUsageException: servantsPerSession reached for b5016d41-0542-4d52-8c23-eba0f408f4da: 10000
                        	at omero.util.ServantHolder.put(ServantHolder.java:172)
                        	at omero.cmd.SessionI.registerServant(SessionI.java:618)
                        	at omero.cmd.SessionI.registerServant(SessionI.java:569)
                        	at omero.cmd.SessionI.submit_async(SessionI.java:210)
                        	at omero.cmd.SessionI.submit_async(SessionI.java:157)
                        	at omero.api._ServiceFactoryTie.submit_async(_ServiceFactoryTie.java:292)
                        	at omero.cmd._SessionDisp.___submit(_SessionDisp.java:102)
                        	at omero.api._ServiceFactoryDisp.__dispatch(_ServiceFactoryDisp.java:1387)
                        	at IceInternal.Incoming.invoke(Incoming.java:221)
                        	at Ice.ConnectionI.invokeAll(ConnectionI.java:2536)
                        	at Ice.ConnectionI.dispatch(ConnectionI.java:1145)
                        	at Ice.ConnectionI.message(ConnectionI.java:1056)
                        	at IceInternal.ThreadPool.run(ThreadPool.java:395)
                        	at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
                        	at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832)
                        	at java.base/java.lang.Thread.run(Thread.java:834)
                        "
    serverExceptionClass = "ome.conditions.OverUsageException"
    message = "servantsPerSession reached for b5016d41-0542-4d52-8c23-eba0f408f4da: 10000"
	at omero.util.ServantHolder.put(ServantHolder.java:171)
	at omero.cmd.SessionI.registerServant(SessionI.java:618)
	at omero.cmd.SessionI.registerServant(SessionI.java:569)
	at omero.cmd.SessionI.submit_async(SessionI.java:210)
	at omero.cmd.SessionI.submit_async(SessionI.java:157)
	at omero.api._ServiceFactoryTie.submit_async(_ServiceFactoryTie.java:292)
	at omero.cmd._SessionDisp.___submit(_SessionDisp.java:102)
	at omero.api._ServiceFactoryDisp.__dispatch(_ServiceFactoryDisp.java:1387)
	at IceInternal.Incoming.invoke(Incoming.java:221)
	at Ice.ConnectionI.invokeAll(ConnectionI.java:2536)
	at Ice.ConnectionI.dispatch(ConnectionI.java:1145)
	at Ice.ConnectionI.message(ConnectionI.java:1056)
	at IceInternal.ThreadPool.run(ThreadPool.java:395)
	at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
	at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832)
	at java.base/java.lang.Thread.run(Thread.java:834)

}

    serverExceptionClass = 
    message = Internal exception
}
!! 01/20/20 22:11:13.019 error: communicator not destroyed during global destruction.

joshmoore · 2020-01-23T16:10:45Z

@will-moore : the second opened table isn't closed:

    open_table = resources.openTable(orig_file)
    open_table.delete()
    open_table.close()  # passes for me with this

patch against docker-example-omero for testing


diff --git a/docker-compose.yml b/docker-compose.yml
index 60fd75c..0e633ad 100644
--- a/docker-compose.yml
+++ b/docker-compose.yml
@@ -21,6 +21,7 @@ services:
       CONFIG_omero_db_pass: omero
       CONFIG_omero_db_name: omero
       ROOTPASS: omero
+      CONFIG_omero_throttling_servants__per__session: 100
     networks:
       - omero
     ports:
@@ -28,6 +29,7 @@ services:
       - "4064:4064"
     volumes:
       - "omero:/OMERO"
+      - ".:/src:ro"
 
   omeroweb:
     image: "openmicroscopy/omero-web-standalone:5.6"
diff --git a/patch b/patch
new file mode 100644
index 0000000..c68c8ea
--- /dev/null
+++ b/patch
@@ -0,0 +1,50 @@
+From 798e26539d4823feae294db322d9712de81f0113 Mon Sep 17 00:00:00 2001
+From: jmoore <josh@glencoesoftware.com>
+Date: Wed, 18 Dec 2019 08:52:49 +0100
+Subject: [PATCH] tables: call delete callback
+
+In testing the table closing logic for 5.5.1, I set up a tight loop to
+create, delete, and close a table. At 10000 servants it failed because
+the callbacks were not being cleaned up. This adds a try/finally block
+in order to do so. Two things to note:
+
+1. Making use of client.submit() is not possible since we only have a
+   ServiceFactoryPrx
+2. I don't believe the nulling of the file_obj was appropriate since
+   that's part of the close logic
+
+transferred from: https://github.com/ome/openmicroscopy/pull/6082
+---
+ src/omero/tables.py | 18 +++++++++---------
+ 1 file changed, 9 insertions(+), 9 deletions(-)
+
+diff --git a/src/omero/tables.py b/src/omero/tables.py
+index 4666e2118..c342909e1 100644
+--- a/src/omero/tables.py
++++ b/src/omero/tables.py
+@@ -321,16 +321,16 @@ def delete(self, current=None):
+             raise
+ 
+         try:
+-            callback.loop(20, 500)
+-        except LockTimeout:
+-            callback.close(True)
+-            raise omero.InternalException(None, None, "delete timed-out")
+-
+-        rsp = callback.getResponse()
+-        if isinstance(rsp, omero.cmd.ERR):
+-            raise omero.InternalException(None, None, str(rsp))
++            try:
++                callback.loop(20, 500)
++            except LockTimeout:
++                raise omero.InternalException(None, None, "delete timed-out")
+ 
+-        self.file_obj = None
++            rsp = callback.getResponse()
++            if isinstance(rsp, omero.cmd.ERR):
++                raise omero.InternalException(None, None, str(rsp))
++        finally:
++            callback.close(True)
+ 
+     # TABLES METADATA API ===========================
+ 
diff --git a/patch.sh b/patch.sh
new file mode 100755
index 0000000..6996978
--- /dev/null
+++ b/patch.sh
@@ -0,0 +1,2 @@
+docker-compose exec -u root omeroserver patch /opt/omero/server/venv3/lib/python3.6/site-packages/omero/tables.py /src/patch
+docker-compose exec -u omero-server omeroserver env OMERODIR=/opt/omero/server/OMERO.server /opt/omero/server/venv3/bin/omero admin ice server stop Tables-0
diff --git a/t.py b/t.py
new file mode 100755
index 0000000..83b0d45
--- /dev/null
+++ b/t.py
@@ -0,0 +1,41 @@
+#!/usr/bin/env python
+from omero.gateway import BlitzGateway
+from random import random
+import omero
+
+conn = BlitzGateway('root', 'omero', port=4064, host='localhost')
+conn.connect()
+
+for i in range(15000):
+  try:
+    print(i)
+    table_name = "TablesDemo:%s" % str(random())
+    col1 = omero.grid.LongColumn('Uid', 'testLong', [])
+    col2 = omero.grid.StringColumn('MyStringColumnInit', '', 64, [])
+    columns = [col1, col2]
+
+    resources = conn.c.sf.sharedResources()
+    repository_id = resources.repositories().descriptions[0].getId().getValue()
+    table = resources.newTable(repository_id, table_name)
+    table.initialize(columns)
+
+    ids = [1, 2, 3, 4, 5, 6, 7, 8, 9, 10]
+    strings = ["one", "two", "three", "four", "five",
+            "six", "seven", "eight", "nine", "ten"]
+    data1 = omero.grid.LongColumn('Uid', 'test Long', ids)
+    data2 = omero.grid.StringColumn('MyStringColumn', '', 64, strings)
+    data = [data1, data2]
+    table.addData(data)
+    orig_file = table.getOriginalFile()
+    table.close()           # when we are done, close.
+
+    open_table = resources.openTable(orig_file)
+    open_table.delete()
+    open_table.close()
+  except Exception as e:
+    if "null table" in str(e):
+      print("null table")
+    else:
+      raise
+print('done')
+conn.close()

will-moore · 2020-01-24T12:20:03Z

OK, with that open_table.close() fix I get much further,
but I'm afraid I'm still seeing the same error when I switch omero-py branch to * 4f9f71a5 (HEAD, snoopy/merge_ci) and run again:

Exception

9995
9996
Traceback (most recent call last):
  File "tabletest.py", line 32, in <module>
    open_table.delete()
  File "/Users/wmoore/Desktop/OMEROPY/omero-py/target/omero_Tables_ice.py", line 1401, in delete
    return _M_omero.grid.Table._op_delete.invoke(self, ((), _ctx))
omero.InternalException: exception ::omero::InternalException
{
    serverStackTrace = Traceback (most recent call last):
  File "/Users/wmoore/Desktop/OMEROPY/omero-py/target/omero/util/decorators.py", line 69, in exc_handler
    rv = func(*args, **kwargs)
  File "/Users/wmoore/Desktop/OMEROPY/omero-py/target/omero/util/decorators.py", line 29, in handler
    return func(*args, **kwargs)
  File "/Users/wmoore/Desktop/OMEROPY/omero-py/target/omero/tables.py", line 312, in delete
    handle = self.factory.submit(dc)
  File "/Users/wmoore/Desktop/OMEROPY/omero-py/target/omero_cmd_API_ice.py", line 951, in submit
    return _M_omero.cmd.Session._op_submit.invoke(self, ((req, ), _ctx))
Ice.UnknownUserException: exception ::Ice::UnknownUserException
{
    unknown = omero::OverUsageException
omero.OverUsageException
    serverStackTrace = "ome.conditions.OverUsageException: servantsPerSession reached for f5d8ecc1-1bbf-4b0c-af4d-e2c897b17766: 10000
                        	at omero.util.ServantHolder.put(ServantHolder.java:172)
                        	at omero.cmd.SessionI.registerServant(SessionI.java:618)
                        	at omero.cmd.SessionI.registerServant(SessionI.java:569)
                        	at omero.cmd.SessionI.submit_async(SessionI.java:210)
                        	at omero.cmd.SessionI.submit_async(SessionI.java:157)
                        	at omero.api._ServiceFactoryTie.submit_async(_ServiceFactoryTie.java:292)
                        	at omero.cmd._SessionDisp.___submit(_SessionDisp.java:102)
                        	at omero.api._ServiceFactoryDisp.__dispatch(_ServiceFactoryDisp.java:1387)
                        	at IceInternal.Incoming.invoke(Incoming.java:221)
                        	at Ice.ConnectionI.invokeAll(ConnectionI.java:2536)
                        	at Ice.ConnectionI.dispatch(ConnectionI.java:1145)
                        	at Ice.ConnectionI.message(ConnectionI.java:1056)
                        	at IceInternal.ThreadPool.run(ThreadPool.java:395)
                        	at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
                        	at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832)
                        	at java.base/java.lang.Thread.run(Thread.java:834)
                        "
    serverExceptionClass = "ome.conditions.OverUsageException"
    message = "servantsPerSession reached for f5d8ecc1-1bbf-4b0c-af4d-e2c897b17766: 10000"
	at omero.util.ServantHolder.put(ServantHolder.java:171)
	at omero.cmd.SessionI.registerServant(SessionI.java:618)
	at omero.cmd.SessionI.registerServant(SessionI.java:569)
	at omero.cmd.SessionI.submit_async(SessionI.java:210)
	at omero.cmd.SessionI.submit_async(SessionI.java:157)
	at omero.api._ServiceFactoryTie.submit_async(_ServiceFactoryTie.java:292)
	at omero.cmd._SessionDisp.___submit(_SessionDisp.java:102)
	at omero.api._ServiceFactoryDisp.__dispatch(_ServiceFactoryDisp.java:1387)
	at IceInternal.Incoming.invoke(Incoming.java:221)
	at Ice.ConnectionI.invokeAll(ConnectionI.java:2536)
	at Ice.ConnectionI.dispatch(ConnectionI.java:1145)
	at Ice.ConnectionI.message(ConnectionI.java:1056)
	at IceInternal.ThreadPool.run(ThreadPool.java:395)
	at IceInternal.ThreadPool.access$300(ThreadPool.java:12)
	at IceInternal.ThreadPool$EventHandlerThread.run(ThreadPool.java:832)
	at java.base/java.lang.Thread.run(Thread.java:834)

}

    serverExceptionClass = 
    message = Internal exception
}

joshmoore · 2020-01-24T15:10:58Z

@will-moore : I've just re-run against merge-ci and am now beyond 10000. Is there any chance that the tables server or similar hadn't been restarted after you moved to snoopy/merge_ci?

will-moore · 2020-01-24T15:41:35Z

More than a chance. A certainty! I'll try again...

joshmoore · 2020-01-24T15:43:12Z

I'm now up to 12138...12139... ;)

will-moore · 2020-01-24T15:44:17Z

Do I just need to restart the server, or something else more Tables-specific?

joshmoore · 2020-01-24T15:46:08Z

Your equivalent of

env OMERODIR=/opt/omero/server/OMERO.server /opt/omero/server/venv3/bin/omero admin ice server stop Tables-0

should suffice.

mtbc · 2020-01-28T15:51:28Z

Locally I don't quite reach 10,000 without this PR, will know tomorrow how I do with it.

mtbc · 2020-01-29T10:20:52Z

With this PR,

...
14997
14998
14999
done

This was referenced Dec 18, 2019

tables: call delete callback ome/openmicroscopy#6082

Closed

Add enter/exit methods to CmdCallback #153

Open

joshmoore force-pushed the master branch from 3568210 to 6842ee6 Compare January 10, 2020 13:17

mtbc approved these changes Jan 29, 2020

View reviewed changes

joshmoore merged commit 4689572 into ome:master Jan 29, 2020

joshmoore deleted the table-del-leak branch January 29, 2020 10:23

joshmoore added this to the 5.6.1 milestone Mar 17, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tables: call delete callback #152

tables: call delete callback #152

joshmoore commented Dec 18, 2019

will-moore commented Jan 20, 2020

joshmoore commented Jan 23, 2020

will-moore commented Jan 24, 2020

joshmoore commented Jan 24, 2020

will-moore commented Jan 24, 2020

joshmoore commented Jan 24, 2020

will-moore commented Jan 24, 2020

joshmoore commented Jan 24, 2020

mtbc commented Jan 28, 2020

mtbc commented Jan 29, 2020

tables: call delete callback #152

tables: call delete callback #152

Conversation

joshmoore commented Dec 18, 2019

will-moore commented Jan 20, 2020

joshmoore commented Jan 23, 2020

will-moore commented Jan 24, 2020

joshmoore commented Jan 24, 2020

will-moore commented Jan 24, 2020

joshmoore commented Jan 24, 2020

will-moore commented Jan 24, 2020

joshmoore commented Jan 24, 2020

mtbc commented Jan 28, 2020

mtbc commented Jan 29, 2020