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 #13246 (new)

Opened 3 years ago

Last modified 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 (10)

comment:1 Changed 3 years ago by atarkowska

  • Cc atarkowska added

comment:2 Changed 3 years ago by atarkowska

  • Priority changed from minor to major

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.

comment:3 Changed 3 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:6 Changed 3 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 3 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: Changed 3 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 3 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 3 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:

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.

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.78112 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!