_openmm fails to load

[Tristan Croll]

The following bug report has been submitted:
Platform:        Windows-10-10.0.18362
ChimeraX Version: 0.92 (2020-01-22)
Description
OpenMM is failing to import its compiled _openmm library in the latest daily builds.

Log:
Startup Messages  
---  
warning | 'clip' is a prefix of an existing command 'clipper'  
  
UCSF ChimeraX version: 0.92 (2020-01-22)  
© 2016-2020 Regents of the University of California. All rights reserved.  
How to cite UCSF ChimeraX  

> open 3io0 format mmCIF fromDatabase pdb structureFactors true

Summary of feedback from opening 3io0 fetched from pdb  
---  
warning | WARNING: multiple experimental reflection datasets found:  
F_meas_au, F_meas_sigma_au,  
pdbx_F_plus, pdbx_F_plus_sigma, pdbx_F_minus, pdbx_F_minus_sigma,  
pdbx_anom_difference, pdbx_anom_difference_sigma,  
intensity_meas, intensity_sigma,  
pdbx_I_plus, pdbx_I_plus_sigma, pdbx_I_minus, pdbx_I_minus_sigma  
Automatically choosing "intensity_meas, intensity_sigma".  
notes | Resolution: 3.003  
Reflection data provided as intensities. Performing French & Wilson scaling to
convert to amplitudes...  
  
3io0 title:  
Crystal structure of EtuB from Clostridium kluyveri [more info...]  
  
Chain information for 3io0  
---  
Chain | Description  
1.1/A | EtuB protein  
  
3io0 mmCIF Assemblies  
---  
1| author_and_software_defined_assembly  
  
  
Traceback (most recent call last):  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\chimerax\core\toolshed\info.py", line 297, in _register_cmd  
api._api_caller.register_command(api, self, ci, logger)  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\chimerax\core\toolshed\\__init__.py", line 1616, in register_command  
return cls._get_func(api, "register_command")(ci.name, logger)  
File "C:\Users\tic20\AppData\Local\UCSF\ChimeraX\0.92\site-
packages\chimerax\isolde\\__init__.py", line 137, in register_command  
cmd.register_isolde(logger)  
File "C:\Users\tic20\AppData\Local\UCSF\ChimeraX\0.92\site-
packages\chimerax\isolde\cmd.py", line 223, in register_isolde  
from chimerax.isolde.manipulations.cmd import register_manip_commands  
File "C:\Users\tic20\AppData\Local\UCSF\ChimeraX\0.92\site-
packages\chimerax\isolde\manipulations\\__init__.py", line 11, in <module>  
from .peptide_flip import Peptide_Bond_Flipper  
File "C:\Users\tic20\AppData\Local\UCSF\ChimeraX\0.92\site-
packages\chimerax\isolde\manipulations\peptide_flip.py", line 11, in <module>  
from ..constants import defaults  
File "C:\Users\tic20\AppData\Local\UCSF\ChimeraX\0.92\site-
packages\chimerax\isolde\constants.py", line 14, in <module>  
from simtk.openmm import VariableLangevinIntegrator, CustomGBForce  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\simtk\openmm\\__init__.py", line 19, in <module>  
from simtk.openmm.openmm import *  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\simtk\openmm\openmm.py", line 28, in <module>  
_openmm = swig_import_helper()  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\simtk\openmm\openmm.py", line 24, in swig_import_helper  
_mod = imp.load_module('_openmm', fp, pathname, description)  
File "C:\Program Files\ChimeraX-Daily\bin\lib\imp.py", line 242, in
load_module  
return load_dynamic(name, filename, file)  
File "C:\Program Files\ChimeraX-Daily\bin\lib\imp.py", line 342, in
load_dynamic  
return _load(spec)  
ImportError: DLL load failed: The specified module could not be found.  
  
During handling of the above exception, another exception occurred:  
  
Traceback (most recent call last):  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\chimerax\core\commands\cli.py", line 2125, in lazy_register  
deferred.call()  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\chimerax\core\commands\cli.py", line 2056, in call  
return self.proxy()  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\chimerax\core\toolshed\info.py", line 287, in cb  
s._register_cmd(ci, l)  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\chimerax\core\toolshed\info.py", line 300, in _register_cmd  
"register_command() failed for command %s in bundle %s:\n%s" % (ci.name,
self.name, str(e)))  
chimerax.core.toolshed.ToolshedError: register_command() failed for command
isolde in bundle ChimeraX-ISOLDE:  
DLL load failed: The specified module could not be found.  
  
During handling of the above exception, another exception occurred:  
  
Traceback (most recent call last):  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\chimerax\cmd_line\tool.py", line 258, in execute  
cmd.run(cmd_text)  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\chimerax\core\commands\cli.py", line 2778, in run  
self._find_command_name(final, used_aliases=_used_aliases)  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\chimerax\core\commands\cli.py", line 2521, in _find_command_name  
what.lazy_register(cmd_name)  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\chimerax\core\commands\cli.py", line 2127, in lazy_register  
raise RuntimeError("delayed command registration for %r failed (%s)" %
(cmd_name, e))  
RuntimeError: delayed command registration for 'isolde' failed
(register_command() failed for command isolde in bundle ChimeraX-ISOLDE:  
DLL load failed: The specified module could not be found.)  
  
RuntimeError: delayed command registration for 'isolde' failed
(register_command() failed for command isolde in bundle ChimeraX-ISOLDE:  
DLL load failed: The specified module could not be found.)  
  
File "C:\Program Files\ChimeraX-Daily\bin\lib\site-
packages\chimerax\core\commands\cli.py", line 2127, in lazy_register  
raise RuntimeError("delayed command registration for %r failed (%s)" %
(cmd_name, e))  
  
See log for complete Python traceback.  
  




OpenGL version: 3.3.0 NVIDIA 426.00
OpenGL renderer: GeForce GTX 1070/PCIe/SSE2
OpenGL vendor: NVIDIA Corporation

[Tristan Croll]

Happened on two independent Windows systems (a new user, and then 
double-checked on my own) at the EMBL EM Validation workshop. Haven't 
tested other platforms yet.

On 2020-01-24 09:13, ChimeraX wrote:

[Tom Goddard]

I reproduced this error on Windows 10 machine vive.cgl.ucsf.edu with Jan 24 daily build.

Importing openmm succeeds if done before any model is opened. Then it will work even after models are open. But importing after "open 1mtx" fails with the reported traceback. Importing after "open pubchem:2719" succeeds. Importing after "marker #1 0,0,0" to make a model with a single marker succeeds, unless you do a mouse hover before the input (over marker or empty space) in which case import fails. Also making the marker then using the "view" command and import fails.

Eric and I theorize that the import failures all happen after ChimeraX opens some other DLL. Maybe loading another DLL causes a conflict with OpenMM opening its own DLLs because of some incompatibility, like different C++ runtime is required.

The January 8 2020 daily build on vive.cgl.ucsf.edu does not have any of these problems.

One change since January 8 is some prereqs like PyOpenGL and numpy were updated.

[Tristan Croll]

It looks like something is knocking ChimeraX\bin off the DLL search 
path. If I monitor with Process Monitor 
(https://docs.microsoft.com/en-us/sysinternals/downloads/procmon) and 
filter for events involving OpenMM, then importing openmm under 
successful and failing scenarios looks like the attached screenshots 
(the failed one goes on for quite a few more pages of "NAME NOT FOUND" 
but never finds OpenMM.DLL).




On 2020-01-25 02:16, ChimeraX wrote:

failed_import.png​

successful_import.png​

[Tristan Croll]

Added by email2trac

[Tristan Croll]

Added by email2trac

[Tristan Croll]

Something is doing something truly evil here - not just on import, but regularly during the main event loop:

# before loading a model
import win32api
d = win32api.GetDllDirectory()
d
Out[2]: 'C:\\Program Files\\ChimeraX-Daily\\bin'

# after loading a model

win32api.GetDllDirectory()
---------------------------------------------------------------------------
error                                     Traceback (most recent call last)
<ipython-input-5-93eb0537a8de> in <module>
----> 1 win32api.GetDllDirectory()

error: (0, 'GetDllDirectory', 'No error message is available')

win32api.SetDllDirectory(d)

win32api.GetDllDirectory()
Out[9]: 'C:\\Program Files\\ChimeraX-Daily\\bin'

# a few seconds later

win32api.GetDllDirectory()
---------------------------------------------------------------------------
error                                     Traceback (most recent call last)
<ipython-input-10-93eb0537a8de> in <module>
----> 1 win32api.GetDllDirectory()

def set_directory_and_load_openmm(d):
    win32api.SetDllDirectory(d)
    from simtk import openmm
    

set_directory_and_load_openmm(d)
# Succeeds

Looks similar in symptoms to this old NumPy bug (​https://github.com/numpy/numpy/issues/11431) but that's long since fixed.

[Tristan Croll]

I found the notes at ​https://github.com/numpy/numpy/wiki/windows-dll-notes really helpful in getting this far, by the way.

[Tristan Croll]

Definitely NumPy's fault. Minimal replication, in a fresh session with no models loaded:

import win32api
win32api.GetDllDirectory()
Out[2]: 'C:\\Program Files\\ChimeraX-Daily\\bin'

import numpy
win32api.GetDllDirectory()
Out[2]: 'C:\\Program Files\\ChimeraX-Daily\\bin'

arr = numpy.identity(3)

win32api.GetDllDirectory()
Out[7]: 'C:\\Program Files\\ChimeraX-Daily\\bin'

 numpy.linalg.inv(arr)
Out[8]: 
array([[1., 0., 0.],
       [0., 1., 0.],
       [0., 0., 1.]])

win32api.GetDllDirectory()
---------------------------------------------------------------------------
error                                     Traceback (most recent call last)
<ipython-input-9-93eb0537a8de> in <module>
----> 1 win32api.GetDllDirectory()

error: (0, 'GetDllDirectory', 'No error message is available')

[Tristan Croll]

Reported as a Numpy bug at ​https://github.com/numpy/numpy/issues/15431. Still a bit confusing: using the above example, if I reinstate the directory with win32api.SetDllDirectory() and run numpy.linalg.inv() again, it doesn't clear it this time - but whatever's doing it in the event loop does. Not sure why this should be.

[Greg Couch]

This might be because we're using Visual Studio 2015 and numpy is built with a newer version. It should be compatible according to ​https://wiki.python.org/moin/WindowsCompilers (Visual Studio 2015 is Visual C++ 14.0). But....

[Tristan Croll]

The Numpy folks have narrowed it down to the new Intel MKL 2020 library calling SetDllDirectory(NULL) on load. They've filed it as a bug on the Intel support forum at ​https://software.intel.com/en-us/forums/intel-math-kernel-library/topic/844125. In the meantime, I guess it might be best to downgrade?

[Tom Goddard]

Ok, reverted numpy 1.18.1 to 1.17.4 -- will be in tonight's ChimeraX builds.

[Tristan Croll]

Thanks!

On 2020-01-28 18:05, ChimeraX wrote:

[Tristan Croll]

Just received a notification that this is fixed in MKL 2020.0.1, so once Numpy-MKL updates to that all should be safe again.

[Greg Couch]

Lastest numpy has the lastest MKL which has the fix. And is installed in daily build.