Infrequent ISOLDE crash

[Tristan Croll]

The following bug report has been submitted:
Platform:        Linux-3.10.0-1062.9.1.el7.x86_64-x86_64-with-centos-7.7.1908-Core
ChimeraX Version: 0.93 (2020-04-03)
Description
I'm still getting a *very* occasional (I estimate less than 1 in 100) segmentation fault when preparing a model for ISOLDE. Being so rare makes it really difficult to pin down exactly which step is causing it, and so far I haven't managed to ever trigger it when running under GDB (which makes me suspect some subtle race condition). As best I can tell, it happens when ISOLDE is started just after doing e.g. "clipper assoc #2 to #1" to assign a cryo-EM map to a model. The tracebacks I get *suggest* it has to do with some Drawing being improperly deleted. Here's an example from a crash *within* ChimeraX:

{{{
Fatal Python error: Aborted

Current thread 0x00007f931a7ed700 (most recent call first):
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/opengl.py", line 134 in make_current
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/drawing.py", line 1122 in delete
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/models.py", line 88 in delete
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/drawing.py", line 1113 in __del__
  File "/home/tic20/.local/share/ChimeraX/0.93/site-packages/chimerax/isolde/openmm/forcefields.py", line 66 in _background_load_ff
  File "/opt/UCSF/ChimeraX/lib/python3.7/concurrent/futures/thread.py", line 57 in run
  File "/opt/UCSF/ChimeraX/lib/python3.7/concurrent/futures/thread.py", line 80 in _worker
  File "/opt/UCSF/ChimeraX/lib/python3.7/threading.py", line 870 in run
  File "/opt/UCSF/ChimeraX/lib/python3.7/threading.py", line 926 in _bootstrap_inner
  File "/opt/UCSF/ChimeraX/lib/python3.7/threading.py", line 890 in _bootstrap

Thread 0x00007f9414d99740 (most recent call first):
  File "/home/tic20/.local/share/ChimeraX/0.93/site-packages/chimerax/clipper/symmetry.py", line 1459 in _update_box
  File "/home/tic20/.local/share/ChimeraX/0.93/site-packages/chimerax/clipper/symmetry.py", line 1605 in _model_changed_cb
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 130 in invoke
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 213 in _activate
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 182 in activate
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 348 in activate_trigger
  File "/home/tic20/.local/share/ChimeraX/0.93/site-packages/chimerax/clipper/symmetry.py", line 622 in _structure_change_cb
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 130 in invoke
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 213 in _activate
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 182 in activate
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 348 in activate_trigger
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/changes.py", line 31 in check_for_changes
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/atomic/__init__.py", line 79 in <lambda>
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 130 in invoke
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 213 in _activate
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 182 in activate
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/triggerset.py", line 348 in activate_trigger
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/commands/cli.py", line 2948 in command_trigger
  File "/opt/UCSF/ChimeraX/lib/python3.7/contextlib.py", line 119 in __exit__
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/commands/cli.py", line 2866 in run
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/cmd_line/tool.py", line 258 in execute
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/cmd_line/tool.py", line 112 in keyPressEvent
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/ui/gui.py", line 268 in event_loop
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/ChimeraX_main.py", line 771 in init
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/ChimeraX_main.py", line 903 in <module>
  File "/opt/UCSF/ChimeraX/lib/python3.7/runpy.py", line 85 in _run_code
  File "/opt/UCSF/ChimeraX/lib/python3.7/runpy.py", line 193 in _run_module_as_main
[8341:8345:0100/000000.235334:ERROR:broker_posix.cc(40)] Recvmsg error: Connection reset by peer (104)
Aborted (core dumped)
}}}

 Line 1459 of clipper/symmetry.py is:

{{{
        atoms = self.structure.atoms
        atoms.hides |=HIDE_ISOLDE # 1459
}}}

Line 66 of isolde/openmm/forcefields.py is

{{{
        forcefield, cached_openmm_version, cached_isolde_version = pickle.load(infile)
}}}

... where forcefield is an OpenMM ForceField object and the other two variables are simple strings. As the method name suggests, this is running in a Python thread. Most likely coincidental that it happened to be in progress when the crash occurred.

While repeatedly looping through the commands:

{{{
open 6kpf
open 0744 from emdb
clipper assoc #2 to #1
isolde start
}}}

... to try to reproduce it I didn't get any hard crashes, but in one instance I got a traceback on *closing* ChimeraX:

{{{
Exception ignored in: <function Drawing.__del__ at 0x7f8eeb4d4560>
Traceback (most recent call last):
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/drawing.py", line 1113, in __del__
    self.delete()
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/models.py", line 88, in delete
    Drawing.delete(self)
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/drawing.py", line 1122, in delete
    c.make_current()	# Make OpenGL context current for deleting OpenGL resources.
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/opengl.py", line 135, in make_current
    raise OpenGLError("Could not make graphics context current")
chimerax.graphics.opengl.OpenGLError: Could not make graphics context current
Exception ignored in: <function Drawing.__del__ at 0x7f8eeb4d4560>
Traceback (most recent call last):
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/drawing.py", line 1113, in __del__
    self.delete()
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/core/models.py", line 88, in delete
    Drawing.delete(self)
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/drawing.py", line 1122, in delete
    c.make_current()	# Make OpenGL context current for deleting OpenGL resources.
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/opengl.py", line 135, in make_current
    raise OpenGLError("Could not make graphics context current")
chimerax.graphics.opengl.OpenGLError: Could not make graphics context current
Exception ignored in: <function Buffer.__del__ at 0x7f8ee5088f80>
Traceback (most recent call last):
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/opengl.py", line 2484, in __del__
    % self.shader_variable_name)
chimerax.graphics.opengl.OpenGLError: OpenGL buffer "position" was not deleted before graphics.Buffer destroyed
Exception ignored in: <function Buffer.__del__ at 0x7f8ee5088f80>
Traceback (most recent call last):
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/opengl.py", line 2484, in __del__
    % self.shader_variable_name)
chimerax.graphics.opengl.OpenGLError: OpenGL buffer "normal" was not deleted before graphics.Buffer destroyed
Exception ignored in: <function Buffer.__del__ at 0x7f8ee5088f80>
Traceback (most recent call last):
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/opengl.py", line 2484, in __del__
    % self.shader_variable_name)
chimerax.graphics.opengl.OpenGLError: OpenGL buffer "vcolor" was not deleted before graphics.Buffer destroyed
Exception ignored in: <function Buffer.__del__ at 0x7f8ee5088f80>
Traceback (most recent call last):
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/opengl.py", line 2484, in __del__
    % self.shader_variable_name)
chimerax.graphics.opengl.OpenGLError: OpenGL buffer "tex_coord" was not deleted before graphics.Buffer destroyed
Exception ignored in: <function Buffer.__del__ at 0x7f8ee5088f80>
Traceback (most recent call last):
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/opengl.py", line 2484, in __del__
    % self.shader_variable_name)
chimerax.graphics.opengl.OpenGLError: OpenGL buffer "position" was not deleted before graphics.Buffer destroyed
Exception ignored in: <function Buffer.__del__ at 0x7f8ee5088f80>
Traceback (most recent call last):
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/opengl.py", line 2484, in __del__
    % self.shader_variable_name)
chimerax.graphics.opengl.OpenGLError: OpenGL buffer "normal" was not deleted before graphics.Buffer destroyed
Exception ignored in: <function Buffer.__del__ at 0x7f8ee5088f80>
Traceback (most recent call last):
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/opengl.py", line 2484, in __del__
    % self.shader_variable_name)
chimerax.graphics.opengl.OpenGLError: OpenGL buffer "vcolor" was not deleted before graphics.Buffer destroyed
Exception ignored in: <function Buffer.__del__ at 0x7f8ee5088f80>
Traceback (most recent call last):
  File "/opt/UCSF/ChimeraX/lib/python3.7/site-packages/chimerax/graphics/opengl.py", line 2484, in __del__
    % self.shader_variable_name)
chimerax.graphics.opengl.OpenGLError: OpenGL buffer "tex_coord" was not deleted before graphics.Buffer destroyed
ObjectCache: Leaked 0004 refs to <P 1>
Segmentation fault (core dumped)
}}}

This has been niggling at me for weeks now, and I'm more-or-less at a loss as to where to go from here. Any suggestions?

OpenGL version: 3.3.0 NVIDIA 440.33.01
OpenGL renderer: TITAN Xp/PCIe/SSE2
OpenGL vendor: NVIDIA Corporation
Manufacturer: Dell Inc.
Model: Precision T5600
OS: CentOS Linux 7 Core
Architecture: 64bit ELF
CPU: 32 Intel(R) Xeon(R) CPU E5-2687W 0 @ 3.10GHz
Cache Size: 20480 KB
Graphics:
	03:00.0 VGA compatible controller [0300]: NVIDIA Corporation GP102 [TITAN Xp] [10de:1b02] (rev a1)
	Subsystem: NVIDIA Corporation Device [10de:11df]
	Kernel driver in use: nvidia

[Eric Pettersen]

From the stack trace, it seems that atomic is firing it's "changes" trigger, and in a handler for that trigger ISOLDE is firing some kind of "structure change" trigger. I would recommend against immediately firing a trigger before other possible "changes" handlers have been able to update whatever state needs updating. Instead, when you decide that you need to fire your trigger, register on the fly a one-shot handler for the "changes done" trigger and have that handler fire your trigger.

--Eric

[Tristan Croll]

Thanks. Will give that a try (happens in quite a few places in the 
code).

On 2020-04-13 17:09, ChimeraX wrote:

[Tristan Croll]

Fixed, I guess... (problem hasn't cropped up in a long long time).