Intermittent crash involving atom copying

[Tristan Croll]

The following bug report has been submitted:
Platform:        Linux-3.10.0-1160.25.1.el7.x86_64-x86_64-with-glibc2.17
ChimeraX Version: 1.4.dev202202090150 (2022-02-09 01:50:51 UTC)
Description
Just updated to the latest daily build, and immediately hit a segmentation fault on doing "isolde demo crystal_intro". After some debugging I've so far worked out that (a) it's intermittent; (b) seemingly only occurs when the atoms' properties are copied to Clipper before the model's been added to the session; and (c) in the cases where it crashes, Clipper reports all the B-factors and occupancies as zero. I take this to mean that there's a race condition where the Python layer is allowing the atoms to be read before the load from file is guaranteed complete?

Log:
> alias preview_toolshed toolshed url https://cxtoolshed-
> preview.rbvi.ucsf.edu; toolshed reload available

> alias production_toolshed toolshed url https://cxtoolshed.rbvi.ucsf.edu;
> toolshed reload available

> isolde shorthand
    
    
    Initialising ISOLDE-specific command aliases:
    Alias	Equivalent full command
    -------------------------------------------------
    st	isolde step {arguments}
    aw	isolde add water {arguments}
    awsf	isolde add water {arguments} sim false
    al	isolde add ligand {arguments}
    aa	isolde add aa $1 sel {arguments}
    ht	isolde mod his sel {arguments}
    so	setattr sel atoms occupancy {arguments}
    ab	isolde adjust bfactors {arguments}
    ss	isolde sim start sel
    rt	isolde release torsions sel {arguments}
    rd	isolde release distances sel {arguments}
    ra	rd; rt
    pf	isolde pepflip sel
    cf	isolde cisflip sel
    cbb	color bfactor {arguments}
    cbo	color byattr occupancy {arguments}
    cbc	color {arguments} bychain; color {arguments} byhet
    cs	clipper set contourSensitivity {arguments}
    

  
UCSF ChimeraX version: 1.4.dev202202090150 (2022-02-09)  
© 2016-2021 Regents of the University of California. All rights reserved.  
How to cite UCSF ChimeraX  




OpenGL version: 3.3.0 NVIDIA 465.19.01
OpenGL renderer: NVIDIA TITAN Xp/PCIe/SSE2
OpenGL vendor: NVIDIA Corporation

Locale: en_GB.UTF-8
Qt version: PyQt5 5.15.2, Qt 5.15.2
Qt platform: xcb

XDG_SESSION_TYPE=x11
DESKTOP_SESSION=gnome-classic
XDG_SESSION_DESKTOP=gnome-classic
XDG_CURRENT_DESKTOP=GNOME-Classic:GNOME
DISPLAY=:0
Manufacturer: Dell Inc.
Model: Precision T5600
OS: CentOS Linux 7 Core
Architecture: 64bit ELF
Virtual Machine: none
CPU: 32 Intel(R) Xeon(R) CPU E5-2687W 0 @ 3.10GHz
Cache Size: 20480 KB
Memory:
	              total        used        free      shared  buff/cache   available
	Mem:            62G        9.0G         21G        301M         31G         52G
	Swap:          4.9G          0B        4.9G

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

Installed Packages:
    alabaster: 0.7.12
    appdirs: 1.4.4
    Babel: 2.9.1
    backcall: 0.2.0
    blockdiag: 3.0.0
    certifi: 2021.10.8
    cftime: 1.5.2
    charset-normalizer: 2.0.11
    ChimeraX-AddCharge: 1.2.3
    ChimeraX-AddH: 2.1.11
    ChimeraX-AlignmentAlgorithms: 2.0
    ChimeraX-AlignmentHdrs: 3.2
    ChimeraX-AlignmentMatrices: 2.0
    ChimeraX-Alignments: 2.2.3
    ChimeraX-AlphaFold: 1.0
    ChimeraX-AltlocExplorer: 1.0.1
    ChimeraX-AmberInfo: 1.0
    ChimeraX-Arrays: 1.0
    ChimeraX-Atomic: 1.36
    ChimeraX-AtomicLibrary: 6.0.1
    ChimeraX-AtomSearch: 2.0
    ChimeraX-AtomSearchLibrary: 1.0
    ChimeraX-AxesPlanes: 2.1
    ChimeraX-BasicActions: 1.1
    ChimeraX-BILD: 1.0
    ChimeraX-BlastProtein: 2.0
    ChimeraX-BondRot: 2.0
    ChimeraX-BugReporter: 1.0
    ChimeraX-BuildStructure: 2.6.1
    ChimeraX-Bumps: 1.0
    ChimeraX-BundleBuilder: 1.1
    ChimeraX-ButtonPanel: 1.0
    ChimeraX-CageBuilder: 1.0
    ChimeraX-CellPack: 1.0
    ChimeraX-Centroids: 1.2
    ChimeraX-ChemGroup: 2.0
    ChimeraX-Clashes: 2.2.2
    ChimeraX-Clipper: 0.18.0
    ChimeraX-ColorActions: 1.0
    ChimeraX-ColorGlobe: 1.0
    ChimeraX-ColorKey: 1.5.1
    ChimeraX-CommandLine: 1.2.1
    ChimeraX-ConnectStructure: 2.0
    ChimeraX-Contacts: 1.0
    ChimeraX-Core: 1.4.dev202202090150
    ChimeraX-CoreFormats: 1.1
    ChimeraX-coulombic: 1.3.2
    ChimeraX-Crosslinks: 1.0
    ChimeraX-Crystal: 1.0
    ChimeraX-CrystalContacts: 1.0
    ChimeraX-DataFormats: 1.2.2
    ChimeraX-Dicom: 1.0
    ChimeraX-DistMonitor: 1.1.5
    ChimeraX-Dssp: 2.0
    ChimeraX-EMDB-SFF: 1.0
    ChimeraX-ExperimentalCommands: 1.0
    ChimeraX-FileHistory: 1.0
    ChimeraX-FunctionKey: 1.0
    ChimeraX-Geometry: 1.1
    ChimeraX-gltf: 1.0
    ChimeraX-Graphics: 1.1
    ChimeraX-Hbonds: 2.1.2
    ChimeraX-Help: 1.2
    ChimeraX-HKCage: 1.3
    ChimeraX-IHM: 1.1
    ChimeraX-ImageFormats: 1.2
    ChimeraX-IMOD: 1.0
    ChimeraX-IO: 1.0.1
    ChimeraX-ISOLDE: 1.4.dev0
    ChimeraX-ItemsInspection: 1.0
    ChimeraX-Label: 1.1
    ChimeraX-LinuxSupport: 1.0
    ChimeraX-ListInfo: 1.1.1
    ChimeraX-Log: 1.1.5
    ChimeraX-LookingGlass: 1.1
    ChimeraX-Maestro: 1.8.1
    ChimeraX-Map: 1.1
    ChimeraX-MapData: 2.0
    ChimeraX-MapEraser: 1.0
    ChimeraX-MapFilter: 2.0
    ChimeraX-MapFit: 2.0
    ChimeraX-MapSeries: 2.1
    ChimeraX-Markers: 1.0
    ChimeraX-Mask: 1.0
    ChimeraX-MatchMaker: 2.0.6
    ChimeraX-MDcrds: 2.6
    ChimeraX-MedicalToolbar: 1.0.1
    ChimeraX-Meeting: 1.0
    ChimeraX-MLP: 1.1
    ChimeraX-mmCIF: 2.7
    ChimeraX-MMTF: 2.1
    ChimeraX-Modeller: 1.5.1
    ChimeraX-ModelPanel: 1.3.1
    ChimeraX-ModelSeries: 1.0
    ChimeraX-Mol2: 2.0
    ChimeraX-Morph: 1.0
    ChimeraX-MouseModes: 1.1
    ChimeraX-Movie: 1.0
    ChimeraX-Neuron: 1.0
    ChimeraX-Nucleotides: 2.0.2
    ChimeraX-OpenCommand: 1.8
    ChimeraX-PDB: 2.6.6
    ChimeraX-PDBBio: 1.0
    ChimeraX-PDBLibrary: 1.0.2
    ChimeraX-PDBMatrices: 1.0
    ChimeraX-PickBlobs: 1.0
    ChimeraX-Positions: 1.0
    ChimeraX-PresetMgr: 1.1
    ChimeraX-PubChem: 2.1
    ChimeraX-ReadPbonds: 1.0.1
    ChimeraX-Registration: 1.1
    ChimeraX-RemoteControl: 1.0
    ChimeraX-ResidueFit: 1.0
    ChimeraX-RestServer: 1.1
    ChimeraX-RNALayout: 1.0
    ChimeraX-RotamerLibMgr: 2.0.1
    ChimeraX-RotamerLibsDunbrack: 2.0
    ChimeraX-RotamerLibsDynameomics: 2.0
    ChimeraX-RotamerLibsRichardson: 2.0
    ChimeraX-SaveCommand: 1.5
    ChimeraX-SchemeMgr: 1.0
    ChimeraX-SDF: 2.0
    ChimeraX-Segger: 1.0
    ChimeraX-Segment: 1.0
    ChimeraX-SelInspector: 1.0
    ChimeraX-SeqView: 2.4.6
    ChimeraX-Shape: 1.0.1
    ChimeraX-Shell: 1.0
    ChimeraX-Shortcuts: 1.1
    ChimeraX-ShowAttr: 1.0
    ChimeraX-ShowSequences: 1.0
    ChimeraX-SideView: 1.0
    ChimeraX-Smiles: 2.1
    ChimeraX-SmoothLines: 1.0
    ChimeraX-SpaceNavigator: 1.0
    ChimeraX-StdCommands: 1.7.7
    ChimeraX-STL: 1.0
    ChimeraX-Storm: 1.0
    ChimeraX-StructMeasure: 1.0.1
    ChimeraX-Struts: 1.0.1
    ChimeraX-Surface: 1.0
    ChimeraX-SwapAA: 2.0
    ChimeraX-SwapRes: 2.1.1
    ChimeraX-TapeMeasure: 1.0
    ChimeraX-Test: 1.0
    ChimeraX-Toolbar: 1.1
    ChimeraX-ToolshedUtils: 1.2.1
    ChimeraX-Tug: 1.0
    ChimeraX-UI: 1.16
    ChimeraX-uniprot: 2.2
    ChimeraX-UnitCell: 1.0
    ChimeraX-ViewDockX: 1.1
    ChimeraX-VIPERdb: 1.0
    ChimeraX-Vive: 1.1
    ChimeraX-VolumeMenu: 1.0
    ChimeraX-VTK: 1.0
    ChimeraX-WavefrontOBJ: 1.0
    ChimeraX-WebCam: 1.0
    ChimeraX-WebServices: 1.0
    ChimeraX-Zone: 1.0
    colorama: 0.4.4
    cxservices: 1.1
    cycler: 0.11.0
    Cython: 0.29.26
    debugpy: 1.5.1
    decorator: 5.1.1
    distro: 1.6.0
    docutils: 0.17.1
    entrypoints: 0.4
    filelock: 3.4.2
    fonttools: 4.29.1
    funcparserlib: 1.0.0a0
    grako: 3.16.5
    h5py: 3.6.0
    html2text: 2020.1.16
    idna: 3.3
    ihm: 0.26
    imagecodecs: 2021.11.20
    imagesize: 1.3.0
    ipykernel: 6.6.1
    ipython: 7.31.1
    ipython-genutils: 0.2.0
    jedi: 0.18.1
    Jinja2: 3.0.3
    jupyter-client: 7.1.0
    jupyter-core: 4.9.1
    kiwisolver: 1.3.2
    line-profiler: 3.4.0
    lxml: 4.7.1
    lz4: 3.1.10
    MarkupSafe: 2.0.1
    matplotlib: 3.5.1
    matplotlib-inline: 0.1.3
    msgpack: 1.0.3
    nest-asyncio: 1.5.4
    netCDF4: 1.5.8
    networkx: 2.6.3
    numexpr: 2.8.1
    numpy: 1.22.1
    openvr: 1.16.802
    packaging: 21.3
    ParmEd: 3.4.3
    parso: 0.8.3
    pexpect: 4.8.0
    pickleshare: 0.7.5
    Pillow: 9.0.0
    pip: 21.3.1
    pkginfo: 1.8.2
    prompt-toolkit: 3.0.27
    psutil: 5.9.0
    ptyprocess: 0.7.0
    pycollada: 0.7.2
    pydicom: 2.2.2
    Pygments: 2.11.2
    PyOpenGL: 3.1.5
    PyOpenGL-accelerate: 3.1.5
    pyparsing: 3.0.7
    PyQt5-commercial: 5.15.2
    PyQt5-sip: 12.8.1
    PyQtWebEngine-commercial: 5.15.2
    python-dateutil: 2.8.2
    pytz: 2021.3
    pyzmq: 22.3.0
    qtconsole: 5.2.2
    QtPy: 2.0.1
    RandomWords: 0.3.0
    requests: 2.27.1
    scipy: 1.7.3
    setuptools: 59.8.0
    sfftk-rw: 0.7.1
    six: 1.16.0
    snowballstemmer: 2.2.0
    sortedcontainers: 2.4.0
    Sphinx: 4.3.2
    sphinx-autodoc-typehints: 1.15.2
    sphinxcontrib-applehelp: 1.0.2
    sphinxcontrib-blockdiag: 3.0.0
    sphinxcontrib-devhelp: 1.0.2
    sphinxcontrib-htmlhelp: 2.0.0
    sphinxcontrib-jsmath: 1.0.1
    sphinxcontrib-qthelp: 1.0.3
    sphinxcontrib-serializinghtml: 1.1.5
    suds-community: 1.0.0
    tables: 3.7.0
    tifffile: 2021.11.2
    tinyarray: 1.2.4
    tornado: 6.1
    traitlets: 5.1.1
    urllib3: 1.26.8
    wcwidth: 0.2.5
    webcolors: 1.11.1
    wheel: 0.37.1
    wheel-filename: 1.3.0

[Tristan Croll]

Just to be clear, the crash itself is inside Clipper’s code. The zero occupancies lead to an empty map, leading to a divide-by-zero when attempting to scale the observed structure factors to match the calculated ones... the minimiser doesn’t handle that, and keeps futilely calculating NaN values until it goes kaput (something I should really fix). But the question is how those zero values are getting through in the first place.

[Eric Pettersen]

Hi Tristan,

The major version number of AtomicLibrary changed, so did you completely recompile everything that uses it?

--Eric

[Tristan Croll]

I did a make clean/make app-install. Can double-check again tomorrow.

[Tristan Croll]

I don't think it was that, though. I tried a number of other things, and the "isolde demo crystal_intro" command was the only one that triggered the crash. Doing "open 3io0 structureFactors true" (essentially the same model/data, just fetched from the PDB) worked fine, as did first manually opening the stored demo model then opening the MTZ as a separate step. In each case where it didn't crash, everything appeared fine. Also, in the 3-4 crashes that I triggered after adding the right logging, the B-factors and occupancies were all strictly zero, not the garbage you usually see from library mismatches.
________________________________
From: ChimeraX <ChimeraX-bugs-admin@cgl.ucsf.edu>
Sent: 10 February 2022 18:56
To: pett@cgl.ucsf.edu <pett@cgl.ucsf.edu>; Tristan Croll <tic20@cam.ac.uk>
Cc: goddard@cgl.ucsf.edu <goddard@cgl.ucsf.edu>
Subject: Re: [ChimeraX] #6131: Intermittent crash involving atom copying

#6131: Intermittent crash involving atom copying
------------------------------------+----------------------
          Reporter:  Tristan Croll  |      Owner:  pett
              Type:  defect         |     Status:  accepted
          Priority:  normal         |  Milestone:
         Component:  Core           |    Version:
        Resolution:                 |   Keywords:
        Blocked By:                 |   Blocking:
Notify when closed:                 |   Platform:  all
           Project:  ChimeraX       |
------------------------------------+----------------------

Comment (by Tristan Croll):

 {{{
 I did a make clean/make app-install. Can double-check again tomorrow.

 }}}

--
Ticket URL: <https://www.rbvi.ucsf.edu/trac/ChimeraX/ticket/6131#comment:4>
ChimeraX <https://www.rbvi.ucsf.edu/chimerax/>
ChimeraX Issue Tracker

[Eric Pettersen]

Yeah, I didn't think that was it because I would expect such a crash to be consistent rather than intermittent. Nonetheless, it was the first thing to ensure. I don't suppose there's any easy way for me to reproduce this myself?

[Eric Pettersen]

Can you print out the occupancies/bfactors before the copy to clipper?

[Tristan Croll]

Can try that tomorrow. For what it's worth, the code that does the copying is at https://github.com/tristanic/chimerax-clipper/blob/bb8e466100850f044dff1a896c39e8d4ad16698e/src/clipper_ext/chimerax_bridge.h#L83 in case it rings any bells. Can send you a build tomorrow if you want to play with it.
________________________________
From: ChimeraX <ChimeraX-bugs-admin@cgl.ucsf.edu>
Sent: 10 February 2022 20:21
Cc: goddard@cgl.ucsf.edu <goddard@cgl.ucsf.edu>; pett@cgl.ucsf.edu <pett@cgl.ucsf.edu>; Tristan Croll <tic20@cam.ac.uk>
Subject: Re: [ChimeraX] #6131: Intermittent crash involving atom copying

#6131: Intermittent crash involving atom copying
------------------------------------+----------------------
          Reporter:  Tristan Croll  |      Owner:  pett
              Type:  defect         |     Status:  accepted
          Priority:  normal         |  Milestone:
         Component:  Core           |    Version:
        Resolution:                 |   Keywords:
        Blocked By:                 |   Blocking:
Notify when closed:                 |   Platform:  all
           Project:  ChimeraX       |
------------------------------------+----------------------

Comment (by pett):

 Can you print out the occupancies/bfactors before the copy to clipper?

--
Ticket URL: <https://www.rbvi.ucsf.edu/trac/ChimeraX/ticket/6131#comment:7>
ChimeraX <https://www.rbvi.ucsf.edu/chimerax/>
ChimeraX Issue Tracker

[Eric Pettersen]

I see you have a non-threaded version of the copying. Can you switch to that to see if it makes a difference?

The mmCIF and PDB file readers don't return until the file has been completely read. They do release the GIL, which allows other Python threads to run, but presumably you don't initiate the copy until the file reader returns. It is pretty much impossible for the occupancy to be zero unless it's been explicitly set to zero (check out Atom::occupancy() and CoordSet::get_occupancy(): ​https://github.com/RBVI/ChimeraX/blob/develop/src/bundles/atomic_lib/atomic_cpp/atomstruct_cpp/Atom.cpp and ​https://github.com/RBVI/ChimeraX/blob/develop/src/bundles/atomic_lib/atomic_cpp/atomstruct_cpp/CoordSet.cpp)

[Tristan Croll]

Actually, despite the name that function is only actually threaded if the total number of atoms is greater than 10,000. This test case only has 3348 atoms, so it just returns the above clipper_atoms_from_cx_atoms()​ in the same thread. Still trying to find some point of commonality about when it happens... it *seems* to be most common on ChimeraX startup - about 20% of the time if it's the first thing I do; just once out of a few dozen times if I load and then close another model first; and once I've successfully run the command once I've yet to see a subsequent failure in the same session. Also, once it's successfully loaded if I start a simulation (which triggers essentially the same code on coordinate updates every time the last map update is done) everything seems to go perfectly, with consistent values on all the logging I've added. Will continue digging...
________________________________
From: ChimeraX <ChimeraX-bugs-admin@cgl.ucsf.edu>
Sent: 11 February 2022 02:15
Cc: goddard@cgl.ucsf.edu <goddard@cgl.ucsf.edu>; pett@cgl.ucsf.edu <pett@cgl.ucsf.edu>; Tristan Croll <tic20@cam.ac.uk>
Subject: Re: [ChimeraX] #6131: Intermittent crash involving atom copying

#6131: Intermittent crash involving atom copying
------------------------------------+----------------------
          Reporter:  Tristan Croll  |      Owner:  pett
              Type:  defect         |     Status:  accepted
          Priority:  normal         |  Milestone:
         Component:  Core           |    Version:
        Resolution:                 |   Keywords:
        Blocked By:                 |   Blocking:
Notify when closed:                 |   Platform:  all
           Project:  ChimeraX       |
------------------------------------+----------------------

Comment (by pett):

 I see you have a non-threaded version of the copying.  Can you switch to
 that to see if it makes a difference?

 The mmCIF and PDB file readers don't return until the file has been
 completely read.  They do release the GIL, which allows other Python
 threads to run, but presumably you don't initiate the copy until the file
 reader returns.  It is pretty much impossible for the occupancy to be zero
 unless it's been explicitly set to zero (check out Atom::occupancy() and
 CoordSet::get_occupancy():
 https://github.com/RBVI/ChimeraX/blob/develop/src/bundles/atomic_lib/atomic_cpp/atomstruct_cpp/Atom.cpp
 and
 https://github.com/RBVI/ChimeraX/blob/develop/src/bundles/atomic_lib/atomic_cpp/atomstruct_cpp/CoordSet.cpp)

--
Ticket URL: <https://www.rbvi.ucsf.edu/trac/ChimeraX/ticket/6131#comment:9>
ChimeraX <https://www.rbvi.ucsf.edu/chimerax/>
ChimeraX Issue Tracker

[Tristan Croll]

OK, so I've added a bunch of logging code to the function that actually copies each ChimeraX atom to a Clipper atom. The upshot is that ChimeraX really is reporting zero occupancy and B-factor (but apparently-correct coords) in the offending cases, both before and after a complete make clean/make app-install (including double-checking that all object files are deleted and deleting the Clipper directories in ~/.local/share/ChimeraX/1.4 for extra peace of mind). Function with logging:

template <class ... Types> clipper::Atom cl_atom_from_cx_atom(atomstruct::Atom* cxatom, Types ... args)
{
    clipper::Atom clatom;
    std::cout << "Altloc: ";
    
    ((std::cout << "," << std::forward<Types>(args)), ...);
    std::cout << " Element: " << cxatom->element().name();
    clatom.set_element(cxatom->element().name());
    const auto& cxcoord = cxatom->coord(args...);
    std::cout << " Coords: " << cxcoord[0] << "," << cxcoord[1] << "," << cxcoord[2];
    clatom.set_coord_orth(clipper::Coord_orth(cxcoord[0], cxcoord[1], cxcoord[2]));
    std::cout << " Occupancy: " << cxatom->occupancy(args...);
    clatom.set_occupancy(cxatom->occupancy(args...));
    std::cout << " B-factor: " << cxatom->bfactor(args...);
    clatom.set_u_iso(clipper::Util::b2u(cxatom->bfactor(args...)));
    auto occ = cxatom->occupancy(args...);
    auto u_iso = clipper::Util::b2u(cxatom->bfactor(args...));
    clipper::U_aniso_orth uani;
    if (cxatom->has_aniso_u(args...))
    {
        const auto& cxau = *(cxatom->aniso_u(args...));
        std::cout << " Anisou: " << cxau[0] << "," << cxau[3] << "," << cxau[5] << "," << cxau[1] << "," << cxau[2] << " " << cxau[4];
        // ChimeraX C++ layer stores aniso_u in row-major order`
        uani = clipper::U_aniso_orth(cxau[0],cxau[3],cxau[5],cxau[1],cxau[2],cxau[4]);
    } else {
        uani = clipper::U_aniso_orth(clipper::U_aniso_orth::null());
    }
    clatom.set_u_aniso_orth(uani);
    std::cout << std::endl;
    return clatom;
}

First few lines of output:

Altloc:  Element: N Coords: 108.497,76.556,64.001 Occupancy: 0 B-factor: 0
Altloc:  Element: C Coords: 108.092,77.384,62.832 Occupancy: 0 B-factor: 0
Altloc:  Element: C Coords: 106.598,77.773,62.855 Occupancy: 0 B-factor: 0
Altloc:  Element: O Coords: 105.928,77.602,63.878 Occupancy: 0 B-factor: 0
Altloc:  Element: C Coords: 108.417,76.493,61.599 Occupancy: 0 B-factor: 0
Altloc:  Element: C Coords: 108.579,75.072,62.147 Occupancy: 0 B-factor: 0
Altloc:  Element: C Coords: 108.967,75.202,63.627 Occupancy: 0 B-factor: 0

Tracing back where this is actually called from... it's called by the Xtal_thread_mgr::init() method at line 859 of ​https://github.com/tristanic/chimerax-clipper/blob/master/src/clipper_ext/xtal_mgr.cpp (sorry - the GitHub site is being weird today and won't give me a direct link to the line). That in turn is wrapped by PyBind11 at line 108 of ​https://github.com/tristanic/chimerax-clipper/blob/master/src/bindings/ext/wrap_xtal_mgr.cpp and called from Python in the constructor of XmapSet at line 441 of ​https://github.com/tristanic/chimerax-clipper/blob/master/src/maps/xmapset.py. That's created in Map_Mgr.add_xmapset_from_file() at line 306 of ​https://github.com/tristanic/chimerax-clipper/blob/master/src/maps/map_mgr.py, which is ultimately called in Isolde.load_crystal_demo() at line 3427 of ​https://github.com/tristanic/isolde/blob/master/isolde/src/isolde.py. Nowhere in any of this am I touching the B-factors or occupancies, so I'm truly mystified.

[Tristan Croll]

Hmm... seems to be nothing to do with Clipper/ISOLDE. In the shell:

from chimerax.open_command.cmd import provider_open
m = provider_open(session, ['/home/tic20/.local/share/ChimeraX/1.4/site-packages/chimerax/isolde/demo_data/3io0/before.pdb'])[0]
print(m.atoms.bfactors.mean())

0.0

In the same session, I tried opening using the open command and colouring by B-factor a half-dozen times, and in all cases the B-factors were zero. Also tried running the above in a loop for a hundred iterations, counting good or bad cases, and the B-factors were zero all 100 times. But after starting a few fresh sessions and finding one where the B-factors were correct on first loading the file, they were correct all 100 times. I'm starting to wonder if my machine might be on the way out... will do some sanity-checking with ChimeraX 1.3, and will also attach the offending PDB file.

[Tristan Croll]

Sometimes opens with zero occ/bfactor, sometimes not

[Tristan Croll]

Behaving fine in 10 from 10 sessions in ChimeraX 1.3.

[Tristan Croll]

This just gets weirder and weirder. In a session where opening via the open command or in the shell via provider_open is consistently failing,

from chimerax.pdb.pdb import open_pdb
with open('/home/tic20/my-gits/isolde/isolde/src/demo_data/3io0/before.pdb', 'rt') as f:
    m = open_pdb(session, f)[0][0]

... gives a model with correct B-factors and occupancies.

[5 min later]

Ah! I think I found it - I believe ViewDockX is the culprit:

         34047 function calls (33912 primitive calls) in 0.054 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.054    0.054 {built-in method builtins.exec}
        1    0.000    0.000    0.054    0.054 <string>:1(<module>)
        1    0.000    0.000    0.054    0.054 cmd.py:126(provider_open)
        1    0.000    0.000    0.041    0.041 cmd.py:423(collated_open)
        1    0.000    0.000    0.038    0.038 cmd.py:425(remember_data_format)
        1    0.000    0.000    0.038    0.038 __init__.py:49(open)
        1    0.008    0.008    0.038    0.038 io.py:413(open_zdock)
        1    0.000    0.000    0.019    0.019 pdb.py:21(open_pdb)


with open('/home/tic20/my-gits/isolde/isolde/src/demo_data/3io0/before.pdb', 'rt') as f:
    m = open_zdock(session, f, 'test.pdb', True, True)[0][0]

m.atoms.bfactors.mean()
0.0

So my guess is that the order of bundle initialization is random, and that whether or not it fails depends on whether ViewDockX gets registered as a provider of PDB opening before or after the actual PDB library.

[Eric Pettersen]

Thanks for tracking and very sorry is was so much trouble. I have committed a fix (namely, having ZDOCK declare itself as not default for .pdb suffix).

[Tristan Croll]

No worries. Had me thinking I was going mad for a little bit there... but it was an interesting experience.

[Tom Goddard]

That was an amazing piece of debugging Tristan!

We have many random startup crashes and certainly ChimeraX should not be doing any initialization in random order that makes these impossible to debug. I've made a ticket to make ChimeraX startup initialize in predictable order #6147 since we have many irreproducible startup crashes and errors that we have never been able to debug.