Task #13246 (closed)
Opened 8 years ago
Closed 3 years ago
LockTimeout due to Inflater infinite loop on APNG (CPU pegged)
Reported by: | omero-qa | Owned by: | jamoore |
---|---|---|---|
Priority: | critical | Milestone: | Unscheduled |
Component: | from QA | Version: | OMERO-5.2.0 |
Keywords: | n.a. | Cc: | david.pinto@…, atarkowska, mlinkert, sbesson, dgault |
Resources: | n.a. | Referenced By: | n.a. |
References: | n.a. | Remaining Time: | n.a. |
Sprint: | n.a. |
Description
https://www.openmicroscopy.org/qa2/qa2/qa/feedback/17219/
Comment: Failed while adding a user as group owner. The group was created by ldap as private when users from the group logged in for the first time. It has no group owner which I'm adding manually now but fails.
Traceback (most recent call last): File "/usr/lib/python2.7/dist-packages/django/core/handlers/base.py", line 111, in get_response response = wrapped_callback(request, *callback_args, **callback_kwargs) File "/home/omero/OMERO.server-5.2.2-ice35-b17/lib/python/omeroweb/decorators.py", line 497, in wrapped retval = f(request, *args, **kwargs) File "/home/omero/OMERO.server-5.2.2-ice35-b17/lib/python/omeroweb/decorators.py", line 547, in wrapper context = f(request, *args, **kwargs) File "/home/omero/OMERO.server-5.2.2-ice35-b17/lib/python/omeroweb/webadmin/views.py", line 725, in manage_group description) File "/home/omero/OMERO.server-5.2.2-ice35-b17/lib/python/omeroweb/webclient/webclient_gateway.py", line 1421, in updateGroup err = self.updatePermissions(group, permissions) File "/home/omero/OMERO.server-5.2.2-ice35-b17/lib/python/omeroweb/webclient/webclient_gateway.py", line 1499, in updatePermissions cb = self.c.submit(command, loops=120) File "/home/omero/OMERO.server-5.2.2-ice35-b17/lib/python/omero/clients.py", line 882, in submit closehandle=True) File "/home/omero/OMERO.server-5.2.2-ice35-b17/lib/python/omero/clients.py", line 901, in waitOnCmd callback.loop(loops, ms) # Throw LockTimeout File "/home/omero/OMERO.server-5.2.2-ice35-b17/lib/python/omero/callbacks.py", line 256, in loop 5000L, int(waited)) LockTimeout: exception ::omero::LockTimeout { serverStackTrace = None serverExceptionClass = None message = Command unfinished after 60.0 seconds backOff = 5000 seconds = 60 } <WSGIRequest path:/webadmin/group/save/1053/, GET:<QueryDict: {}>, POST:<QueryDict: {u'owners': [u'2604'], u'name': [u'castellogroup'], u'description': [u'Minions of the Dark Lord'], u'members': [u'2602', u'2603', u'2652', u'2605'], u'csrfmiddlewaretoken': [u'Yn70HCFw1o1uWtS2IiBA8EgCUZfxCSL2'], u'permissions': [u'0']}>, COOKIES:{'__utma': '230256527.426554350.1456495632.1456495632.1456495632.1', '__utmz': '230256527.1456495632.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)', 'csrftoken': 'Yn70HCFw1o1uWtS2IiBA8EgCUZfxCSL2', 'dontShowCookieNotice': 'TRUE', 'sessionid': 'nh26e4dgms8w0nw26kl8dpityc4akahj'}, META:{'CONTENT_LENGTH': '186', 'CONTENT_TYPE': 'application/x-www-form-urlencoded', 'CONTEXT_DOCUMENT_ROOT': '/var/www/html', 'CONTEXT_PREFIX': '', u'CSRF_COOKIE': u'Yn70HCFw1o1uWtS2IiBA8EgCUZfxCSL2', 'DOCUMENT_ROOT': '/var/www/html', 'GATEWAY_INTERFACE': 'CGI/1.1', 'HTTP_ACCEPT': 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8', 'HTTP_ACCEPT_ENCODING': 'gzip, deflate', 'HTTP_ACCEPT_LANGUAGE': 'en-GB,en;q=0.5', 'HTTP_CONNECTION': 'keep-alive', 'HTTP_COOKIE': 'csrftoken=Yn70HCFw1o1uWtS2IiBA8EgCUZfxCSL2; dontShowCookieNotice=TRUE; __utma=230256527.426554350.1456495632.1456495632.1456495632.1; __utmz=230256527.1456495632.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none); sessionid=nh26e4dgms8w0nw26kl8dpityc4akahj', 'HTTP_DNT': '1', 'HTTP_HOST': 'omero1.bioch.ox.ac.uk', 'HTTP_REFERER': 'https://omero1.bioch.ox.ac.uk/webadmin/group/edit/1053/', 'HTTP_USER_AGENT': 'Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Firefox/38.0 Iceweasel/38.7.1', 'PATH_INFO': u'/webadmin/group/save/1053/', 'PATH_TRANSLATED': '/home/omero/OMERO.server-5.2.2-ice35-b17/lib/python/omeroweb/wsgi.py/webadmin/group/save/1053/', 'QUERY_STRING': '', 'REMOTE_ADDR': '129.67.72.235', 'REMOTE_PORT': '56960', 'REQUEST_METHOD': 'POST', 'REQUEST_SCHEME': 'https', 'REQUEST_URI': '/webadmin/group/save/1053/', 'SCRIPT_FILENAME': '/home/omero/OMERO.server-5.2.2-ice35-b17/lib/python/omeroweb/wsgi.py', 'SCRIPT_NAME': u'', 'SERVER_ADDR': '129.67.75.47', 'SERVER_ADMIN': '[no address given]', 'SERVER_NAME': 'omero1.bioch.ox.ac.uk', 'SERVER_PORT': '443', 'SERVER_PROTOCOL': 'HTTP/1.1', 'SERVER_SIGNATURE': '<address>Apache/2.4.10 (Debian) Server at omero1.bioch.ox.ac.uk Port 443</address>\n', 'SERVER_SOFTWARE': 'Apache/2.4.10 (Debian)', 'SSL_TLS_SNI': 'omero1.bioch.ox.ac.uk', 'apache.version': (2, 4, 10), 'mod_wsgi.application_group': '', 'mod_wsgi.callable_object': 'application', 'mod_wsgi.daemon_connects': '1', 'mod_wsgi.daemon_restarts': '0', 'mod_wsgi.daemon_start': '1464883070518736', 'mod_wsgi.enable_sendfile': '0', 'mod_wsgi.handler_script': '', 'mod_wsgi.input_chunked': '0', 'mod_wsgi.listener_host': '', 'mod_wsgi.listener_port': '443', 'mod_wsgi.process_group': 'omeroweb', 'mod_wsgi.queue_start': '1464883070518654', 'mod_wsgi.request_handler': 'wsgi-script', 'mod_wsgi.request_start': '1464883070518526', 'mod_wsgi.script_reloading': '1', 'mod_wsgi.script_start': '1464883070518758', 'mod_wsgi.version': (4, 3, 0), 'wsgi.errors': <mod_wsgi.Log object at 0x7f75b5ebd270>, 'wsgi.file_wrapper': <type 'mod_wsgi.FileWrapper'>, 'wsgi.input': <mod_wsgi.Input object at 0x7f75b6bf03b0>, 'wsgi.multiprocess': True, 'wsgi.multithread': False, 'wsgi.run_once': False, 'wsgi.url_scheme': 'https', 'wsgi.version': (1, 0)}>
Change History (11)
comment:1 Changed 8 years ago by atarkowska
- Cc atarkowska added
comment:2 Changed 8 years ago by atarkowska
- Priority changed from minor to major
comment:3 Changed 8 years ago by omero
OP says:
While this issue happened while trying to set the owner of a group without a owner, turns out that timeout had already been happening over a few days. Even "sessions who" was timing out. While users were able to login and see the data, all image imports were also failing. top was showing 500% CPU usage. Restarting omero fixed the issue.
Checking the server logs, timeout errors started on May 31. The last non-timeout error was about a missing file that had been imported several days before. Grepping the last log for the filepath and ERROR (and removing session keys):
2016-05-31 13:42:23,734 INFO [ ome.io.nio.FilePathResolver] (.Server-52) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:42:23,797 DEBUG [ loci.formats.Memoizer] (.Server-52) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:42:23,829 INFO [ ome.io.nio.PixelsService] (.Server-52) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 6 2016-05-31 13:42:25,826 INFO [ ome.io.nio.FilePathResolver] (.Server-51) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:42:25,860 DEBUG [ loci.formats.Memoizer] (.Server-51) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:42:25,861 INFO [ ome.io.nio.PixelsService] (.Server-51) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 22 2016-05-31 13:42:28,588 INFO [ ome.io.nio.FilePathResolver] (.Server-51) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:42:28,619 DEBUG [ loci.formats.Memoizer] (.Server-51) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:42:28,620 INFO [ ome.io.nio.PixelsService] (.Server-51) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 22 2016-05-31 13:42:28,729 INFO [ ome.io.nio.FilePathResolver] (.Server-52) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:42:28,759 DEBUG [ loci.formats.Memoizer] (.Server-52) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:42:28,760 INFO [ ome.io.nio.PixelsService] (.Server-52) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 22 2016-05-31 13:42:28,851 INFO [ ome.io.nio.FilePathResolver] (.Server-55) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:42:28,881 DEBUG [ loci.formats.Memoizer] (.Server-55) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:42:28,882 INFO [ ome.io.nio.PixelsService] (.Server-55) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 22 2016-05-31 13:42:32,131 DEBUG [ loci.formats.Memoizer] (.Server-55) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:42:41,649 INFO [ ome.io.nio.FilePathResolver] (.Server-46) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:42:41,682 DEBUG [ loci.formats.Memoizer] (.Server-46) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:42:41,683 INFO [ ome.io.nio.PixelsService] (.Server-46) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 17 2016-05-31 13:42:41,808 INFO [ ome.io.nio.FilePathResolver] (.Server-46) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:42:41,839 DEBUG [ loci.formats.Memoizer] (.Server-46) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:42:41,840 INFO [ ome.io.nio.PixelsService] (.Server-46) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 17 2016-05-31 13:42:42,026 INFO [ ome.io.nio.FilePathResolver] (.Server-50) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:42:42,056 DEBUG [ loci.formats.Memoizer] (.Server-50) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:42:42,057 INFO [ ome.io.nio.PixelsService] (.Server-50) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 17 2016-05-31 13:42:42,149 INFO [ ome.io.nio.FilePathResolver] (.Server-56) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:42:42,179 DEBUG [ loci.formats.Memoizer] (.Server-56) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:42:42,180 INFO [ ome.io.nio.PixelsService] (.Server-56) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 17 2016-05-31 13:42:44,745 DEBUG [ loci.formats.Memoizer] (.Server-54) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:43:11,102 INFO [ ome.io.nio.FilePathResolver] (.Server-50) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:43:11,134 DEBUG [ loci.formats.Memoizer] (.Server-50) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:43:11,136 INFO [ ome.io.nio.PixelsService] (.Server-50) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 9 2016-05-31 13:43:12,253 INFO [ ome.io.nio.FilePathResolver] (.Server-54) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:43:12,284 DEBUG [ loci.formats.Memoizer] (.Server-54) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:43:12,285 INFO [ ome.io.nio.PixelsService] (.Server-54) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 9 2016-05-31 13:43:12,382 INFO [ ome.io.nio.FilePathResolver] (.Server-46) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:43:12,412 DEBUG [ loci.formats.Memoizer] (.Server-46) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:43:12,413 INFO [ ome.io.nio.PixelsService] (.Server-46) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 9 2016-05-31 13:43:12,500 INFO [ ome.io.nio.FilePathResolver] (.Server-52) Metadata only file, resulting path: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv 2016-05-31 13:43:12,531 DEBUG [ loci.formats.Memoizer] (.Server-52) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:43:12,532 INFO [ ome.io.nio.PixelsService] (.Server-52) Creating BfPixelBuffer: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv Series: 9 2016-05-31 13:43:16,567 DEBUG [ loci.formats.Memoizer] (.Server-50) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:44:33,384 DEBUG [ loci.formats.Memoizer] (.Server-53) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 13:44:36,937 INFO [ ome.services.util.ServiceHandler] (2-thread-2) Rslt: ((DeleteLog<event=5997618file=3809323owner=2603group=1053path=bioc1392_2603/2016-05/24/16-40-50.388/na), (DeleteLog<event=5997618file=3809324owner=2603group=1053path=bioc1392_2603/2016-05/24/16-40-50.388/na), (DeleteLog<event=5997618file=3809327owner=2603group=1053path=bioc1392_2603/2016-05/24/16-43-55.417/na), ... 6 more) 2016-05-31 13:44:36,973 INFO [ ome.services.util.ServiceHandler] (2-thread-2) Executor.doWork -- ome.services.blitz.repo.RepositoryDaoImpl.deleteRepoDeleteLogs[(DeleteLog<event=5997618file=3809322owner=2603group=1053path=bioc1392_2603/2016-05/24/name=16-40-50.3, DeleteLog<event=5997618file=3809324owner=2603group=1053path=bioc1392_2603/2016-05/24/16-40-50.388/na, DeleteLog<event=5997618file=3809323owner=2603group=1053path=bioc1392_2603/2016-05/24/16-40-50.388/na, ... 6 more)] 2016-05-31 14:13:40,828 DEBUG [ loci.formats.Memoizer] (2-thread-1) loaded memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo (63801 bytes) 2016-05-31 14:13:40,829 INFO [ loci.formats.Memoizer] (2-thread-1) could not reopen file - deleting invalid memo file: /mnt/OMERO/BioFormatsCache/mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/.MockhdsRNA5.3_R3D_D3D_cons_D3D.dv.bfmemo 2016-05-31 14:13:40,850 ERROR [ ome.io.bioformats.BfPixelBuffer] (2-thread-1) Failed to instantiate BfPixelsWrapper with /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv java.lang.RuntimeException: java.io.FileNotFoundException: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv (No such file or directory) Caused by: java.io.FileNotFoundException: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv (No such file or directory) 2016-05-31 14:13:40,871 INFO [ ome.services.util.ServiceHandler] (2-thread-1) Excp: java.lang.RuntimeException: java.io.FileNotFoundException: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv (No such file or directory) 2016-05-31 14:13:40,873 ERROR [ome.services.blitz.impl.RenderingEngineI] (2-thread-1) Error on close, stage1 java.io.FileNotFoundException: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv (No such file or directory) 2016-05-31 14:13:40,906 ERROR [ omero.cmd.SessionI] (2-thread-1) Error destroying servant: deb19-anonymousomero.api.RenderingEngine=ome.services.blitz.impl.RenderingEngineI@72eb8428 java.io.FileNotFoundException: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv (No such file or directory) java.io.FileNotFoundException: /mnt/OMERO/ManagedRepository/bioc1392_2603/2016-05/24/16-40-50.388/MockhdsRNA5.3_R3D_D3D_cons_D3D.dv (No such file or directory)" 2016-05-31 15:25:40,769 ERROR [ ome.services.blitz.fire.SessionManagerI] (2-thread-1) Error reaping session 01c30967-anonymous from client 5d3da9d0-anonymous 2016-05-31 18:27:08,877 ERROR [ ome.services.util.ServiceHandler] (2-thread-1) Method interface ome.services.util.Executor$Work.doWork invocation took 21981 2016-05-31 20:20:04,143 ERROR [ ome.services.util.ServiceHandler] (2-thread-2) Method interface ome.services.util.Executor$Work.doWork invocation took 62430 2016-05-31 20:20:07,002 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 20877 2016-05-31 20:20:33,441 ERROR [ ome.services.util.ServiceHandler] (2-thread-1) Method interface ome.services.util.Executor$Work.doWork invocation took 21064 2016-05-31 20:22:46,108 ERROR [ ome.services.util.ServiceHandler] (2-thread-1) Method interface ome.services.util.Executor$Work.doWork invocation took 20455 2016-05-31 20:23:31,714 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 20450 2016-05-31 20:26:12,016 ERROR [ ome.services.util.ServiceHandler] (2-thread-1) Method interface ome.services.util.Executor$Work.doWork invocation took 22513 2016-05-31 20:29:07,773 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 20155 2016-05-31 20:35:13,332 ERROR [ ome.services.util.ServiceHandler] (2-thread-4) Method interface ome.services.util.Executor$Work.doWork invocation took 21162 2016-05-31 20:37:11,598 ERROR [ ome.services.util.ServiceHandler] (2-thread-2) Method interface ome.services.util.Executor$Work.doWork invocation took 20654 2016-05-31 20:37:27,770 ERROR [ ome.services.util.ServiceHandler] (2-thread-5) Method interface ome.services.util.Executor$Work.doWork invocation took 208352 2016-05-31 20:41:13,922 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 23720 2016-05-31 20:45:11,997 ERROR [ ome.services.util.ServiceHandler] (2-thread-1) Method interface ome.services.util.Executor$Work.doWork invocation took 23035 2016-05-31 20:47:22,476 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 22686 2016-05-31 20:49:21,336 ERROR [ ome.services.util.ServiceHandler] (2-thread-4) Method interface ome.services.util.Executor$Work.doWork invocation took 20518 2016-05-31 20:51:23,433 ERROR [ ome.services.util.ServiceHandler] (2-thread-4) Method interface ome.services.util.Executor$Work.doWork invocation took 30518 2016-05-31 20:53:08,088 ERROR [ ome.services.util.ServiceHandler] (2-thread-4) Method interface ome.services.util.Executor$Work.doWork invocation took 20755 2016-05-31 20:54:13,469 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 20176 2016-05-31 20:54:52,852 ERROR [ ome.services.util.ServiceHandler] (2-thread-4) Method interface ome.services.util.Executor$Work.doWork invocation took 25342 2016-05-31 20:55:20,239 ERROR [ ome.services.util.ServiceHandler] (2-thread-3) Method interface ome.services.util.Executor$Work.doWork invocation took 21431 [...]
comment:4 Changed 8 years ago by atarkowska
comment:5 Changed 8 years ago by atarkowska
comment:6 Changed 8 years ago by jamoore
Relevant trace:
"pool-2-thread-5" prio=10 tid=0x00007f3238009800 nid=0x4fa7 runnable [0x00007f32ab4f2000] java.lang.Thread.State: RUNNABLE at java.util.zip.Inflater.inflateBytes(Native Method) at java.util.zip.Inflater.inflate(Inflater.java:259) - locked <0x00000004073cc8e8> (a java.util.zip.ZStreamRef) at java.util.zip.InflaterInputStream.read(InflaterInputStream.java:152) at loci.formats.in.APNGReader.decode(APNGReader.java:389) at loci.formats.in.APNGReader.openBytes(APNGReader.java:154) at loci.formats.ImageReader.openBytes(ImageReader.java:453) at loci.formats.ChannelFiller.openBytes(ChannelFiller.java:156) at loci.formats.ChannelFiller.openBytes(ChannelFiller.java:148) at loci.formats.ChannelSeparator.openBytes(ChannelSeparator.java:196) at loci.formats.ReaderWrapper.openBytes(ReaderWrapper.java:349) at loci.formats.ReaderWrapper.openBytes(ReaderWrapper.java:349) at loci.formats.MinMaxCalculator.openBytes(MinMaxCalculator.java:269) at ome.services.blitz.repo.ManagedImportRequestI.parseDataByPlane(ManagedImportRequestI.java:831) at ome.services.blitz.repo.ManagedImportRequestI.parseData(ManagedImportRequestI.java:762) at ome.services.blitz.repo.ManagedImportRequestI.pixelData(ManagedImportRequestI.java:641) at ome.services.blitz.repo.ManagedImportRequestI.step(ManagedImportRequestI.java:494) at omero.cmd.HandleI.steps(HandleI.java:438) at omero.cmd.HandleI$1.doWork(HandleI.java:366)
Repeats 5 times:
/tmp/17227 $ grep APNGReader.decode 2016-06-06-15_59.jstack at loci.formats.in.APNGReader.decode(APNGReader.java:389) at loci.formats.in.APNGReader.decode(APNGReader.java:389) at loci.formats.in.APNGReader.decode(APNGReader.java:389) at loci.formats.in.APNGReader.decode(APNGReader.java:389) at loci.formats.in.APNGReader.decode(APNGReader.java:389)
comment:7 Changed 8 years ago by omero
Would it help it I tracked down those png files? Is there a way to do it other than running from the ManagedRepositories? directory:
{{
find -maxdepth 2 -type d -name 2016-06 -exec find '{}' -name '*png' \;
}}
comment:8 follow-up: ↓ 9 Changed 8 years ago by jamoore
How big are these images? Are these also being processed into pyramids? If so, is it the main Java process which is using all the CPU, or PixelData??
comment:9 in reply to: ↑ 8 Changed 8 years ago by omero
Replying to jamoore:
How big are these images?
Fairly small. There's 60 pngs, between 300K and 3M each.
Are these also being processed into pyramids?
How can I find that out? Actually, how can I find out which of the 60 images have stalled? There's 5 threads reading png, and CPU usage is at 500%. I can match the thread number on jstack to the thread number on the Blitz log. Would that help?
If so, is it the main Java process which is using all the CPU, or PixelData??
It is the main java process.
comment:10 Changed 8 years ago by jamoore
- Cc mlinkert sbesson dgault added
- Priority changed from major to critical
- Summary changed from LockTimeout to LockTimeout due to Inflater infinite loop on APNG (CPU pegged)
As discussing with David (https://openmicroscopy.slack.com/archives/irc/p1465385969000127) this looks to be an (open?)jdk bug:
- https://bugs.openjdk.java.net/browse/JDK-8060193
- https://issues.jenkins-ci.org/browse/JENKINS-14362
- http://stackoverflow.com/questions/6584765/thread-locking-when-flushing-jsp-file
Related OME code:
InflaterInputStream decompressor = new InflaterInputStream(bytes); try { int n = 0; for (int row=0; row<height; row++) { n = 0; while (n < 1) { n = decompressor.read(filters, row, 1); <-- here
At least one thread mentioned that this may not be thread-safe.
comment:11 Changed 3 years ago by sbesson
- Resolution set to fixed
- Status changed from new to closed
Should be fixed by https://github.com/ome/bioformats/pull/3633
carandraug: turns out it had nothing to do with the group not having an owner. I still don't know what causes it, but everything was timing out. I had to restart the server... Also, the server was timing out for several days. People could log in and see the data but were not able to import images, I couldn't set any permissions. Even "sessions who" was timing out.