aiida-core
aiida-core copied to clipboard
Published
20 hours ago •
aiidateam
aiidateam
tests/manage/test_profile_access.py::test_access_control consistently fails (on OSX)
With current develop, I consistently get:
(base) aiida_core_develop/$ tox tests/manage/test_profile_access.py::test_access_control
py38-django develop-inst-noop: /Users/chrisjsewell/Documents/GitHub/aiida_core_develop
py38-django installed: -e git+https://github.com/chrisjsewell/aiida_core.git@fe1acf9f6d425d1be973e3ecd33f19760f59e77c#egg=aiida_core,aiida-export-migration-tests==0.9.0,aio-pika==6.8.0,aiormq==3.3.1,alabaster==0.7.12,aldjemy==2.6,alembic==1.7.5,aniso8601==9.0.1,appnope==0.1.2,archive-path==0.3.6,argon2-cffi==21.1.0,ase==3.22.0,asn1crypto==1.4.0,async-generator==1.10,attrs==21.2.0,Babel==2.9.1,backcall==0.2.0,bcrypt==3.2.0,beautifulsoup4==4.10.0,bleach==4.1.0,certifi==2021.10.8,cffi==1.15.0,charset-normalizer==2.0.8,circus==0.17.1,click==8.0.3,click-config-file==0.6.0,click-spinner==0.1.10,configobj==5.0.6,coverage==4.5.4,cryptography==36.0.0,cycler==0.11.0,debugpy==1.5.1,decorator==5.1.0,defusedxml==0.7.1,deprecation==2.1.0,disk-objectstore==0.6.0,Django==2.2.26,docutils==0.15.2,entrypoints==0.3,Flask==1.1.2,Flask-Cors==3.0.10,Flask-RESTful==0.3.9,fonttools==4.28.2,future==0.18.2,graphviz==0.19,greenlet==1.1.2,idna==3.3,imagesize==1.3.0,importlib-metadata==4.8.2,importlib-resources==5.4.0,iniconfig==1.1.1,ipykernel==6.5.1,ipython==7.30.0,ipython-genutils==0.2.0,ipywidgets==7.6.5,itsdangerous==2.0.1,jedi==0.18.1,Jinja2==3.0.3,jsonschema==3.2.0,jupyter==1.0.0,jupyter-client==6.1.12,jupyter-console==6.4.0,jupyter-core==4.9.1,jupyterlab-pygments==0.1.2,jupyterlab-widgets==1.0.2,kiwipy==0.7.5,kiwisolver==1.3.2,Mako==1.1.6,MarkupSafe==2.0.1,matplotlib==3.5.0,matplotlib-inline==0.1.3,mistune==0.8.4,monty==2021.8.17,mpmath==1.2.1,multidict==5.2.0,nbclient==0.5.9,nbconvert==6.3.0,nbformat==5.1.3,nest-asyncio==1.4.3,networkx==2.6.3,notebook==6.4.5,numpy==1.21.4,packaging==21.3,palettable==3.3.0,pamqp==2.3.0,pandas==1.3.4,pandocfilters==1.5.0,paramiko==2.8.1,parso==0.8.3,pexpect==4.8.0,pg8000==1.23.0,pgsu==0.2.1,pgtest==1.3.2,pickleshare==0.7.5,Pillow==9.0.0,plotly==5.4.0,pluggy==1.0.0,plumpy==0.20.0,prometheus-client==0.12.0,prompt-toolkit==3.0.23,psutil==5.8.0,psycopg2-binary==2.8.6,ptyprocess==0.7.0,py==1.11.0,py-cpuinfo==8.0.0,PyCifRW==4.4.3,pycparser==2.21,pydata-sphinx-theme==0.6.3,Pygments==2.10.0,pymatgen==2022.0.16,Pympler==0.9,PyMySQL==0.9.3,PyNaCl==1.4.0,pyparsing==2.4.7,pyrsistent==0.18.0,pytest==6.2.5,pytest-asyncio==0.16.0,pytest-benchmark==3.4.1,pytest-cov==2.10.1,pytest-datadir==1.3.1,pytest-regressions==2.2.0,pytest-rerunfailures==9.1.1,pytest-timeout==1.4.2,python-dateutil==2.8.2,python-memcached==1.59,pytray==0.3.2,pytz==2021.3,PyYAML==5.4.1,pyzmq==22.3.0,qtconsole==5.2.1,QtPy==1.11.2,requests==2.26.0,ruamel.yaml==0.17.17,ruamel.yaml.clib==0.2.6,scipy==1.7.3,scramp==1.4.1,seekpath==1.9.7,Send2Trash==1.8.0,setuptools-scm==6.3.2,shortuuid==1.0.8,simplejson==3.17.6,six==1.16.0,snowballstemmer==2.2.0,soupsieve==2.3.1,spglib==1.16.1,Sphinx==3.2.1,sphinx-copybutton==0.3.3,sphinx-notfound-page==0.8,sphinx-panels==0.5.2,sphinx-sqlalchemy==0.1.1,sphinxcontrib-applehelp==1.0.2,sphinxcontrib-details-directive==0.1.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,sphinxext-rediraffe==0.2.7,SQLAlchemy==1.4.27,sqlalchemy-diff==0.1.5,SQLAlchemy-Utils==0.37.9,sqlparse==0.4.2,sympy==1.9,tabulate==0.8.9,tenacity==8.0.1,terminado==0.12.1,testpath==0.5.0,toml==0.10.2,tomli==1.2.2,tornado==6.1,tqdm==4.62.3,traitlets==5.1.1,tzlocal==2.1,uncertainties==3.1.6,upf-to-json==0.9.3,urllib3==1.26.7,wcwidth==0.2.5,webencodings==0.5.1,Werkzeug==2.0.2,widgetsnbextension==3.5.2,wrapt==1.11.2,yarl==1.7.2,zipp==3.6.0
py38-django run-test-pre: PYTHONHASHSEED='2626801613'
py38-django run-test: commands[0] | pytest tests/manage/test_profile_access.py::test_access_control
=============================================================================================== test session starts ================================================================================================
platform darwin -- Python 3.8.12, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
cachedir: .tox/py38-django/.pytest_cache
benchmark: 3.4.1 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000)
rootdir: /Users/chrisjsewell/Documents/GitHub/aiida_core_develop, configfile: pyproject.toml
plugins: asyncio-0.16.0, benchmark-3.4.1, datadir-1.3.1, rerunfailures-9.1.1, regressions-2.2.0, cov-2.10.1, timeout-1.4.2
collected 1 item
tests/manage/test_profile_access.py F [100%]
===================================================================================================== FAILURES =====================================================================================================
_______________________________________________________________________________________________ test_access_control ________________________________________________________________________________________________
profile_access_manager = <aiida.manage.profile_access.ProfileAccessManager object at 0x7fd30dd72af0>
def test_access_control(profile_access_manager):
"""Tests the request_access method indirectly.
This test is performed in an integral way because the underlying methods used
have all been tested elsewhere, and it is more relevant to indirectly verify
that this method works in real life scenarios, rather than checking the specifics
of its internal logical structure.
"""
accessing_process = MockProcess(profile_access_manager.profile)
> accessing_pid = accessing_process.start()
tests/manage/test_profile_access.py:258:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
tests/manage/test_profile_access.py:231: in start
self._wait_for_checkfile(temppath_checkfile)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
self = <tests.manage.test_profile_access.MockProcess object at 0x7fd30b55f760>, temppath_checkfile = PosixPath('temp_file.log')
def _wait_for_checkfile(self, temppath_checkfile): # pylint: disable=no-self-use
"""Auxiliary function that waits for the checkfile to be written."""
import time
check_count = 0
while check_count < 100 and not temppath_checkfile.exists():
time.sleep(0.1)
check_count += 1
if check_count == 100:
> raise RuntimeError('Process loading was too slow!')
E RuntimeError: Process loading was too slow!
tests/manage/test_profile_access.py:211: RuntimeError
------------------------------------------------------------------------------------------------ Captured log setup ------------------------------------------------------------------------------------------------
DEBUG pgsu:__init__.py:141 Trying to connect via "psycopg2"...
================================================================================================= warnings summary =================================================================================================
aiida/manage/tests/unittest_classes.py:23
/Users/chrisjsewell/Documents/GitHub/aiida_core_develop/aiida/manage/tests/unittest_classes.py:23: AiidaDeprecationWarning: This module has been deprecated and will be removed soon. Please use the `pytest` fixtures instead.
See https://github.com/aiidateam/aiida-core/wiki/AiiDA-2.0-plugin-migration-guide#unit-tests
warnings.warn( # pylint: disable=no-member
.tox/py38-django/lib/python3.8/site-packages/sphinx/util/docutils.py:45
/Users/chrisjsewell/Documents/GitHub/aiida_core_develop/.tox/py38-django/lib/python3.8/site-packages/sphinx/util/docutils.py:45: DeprecationWarning: distutils Version classes are deprecated. Use packaging.version instead.
__version_info__ = tuple(LooseVersion(docutils.__version__).version)
.tox/py38-django/lib/python3.8/site-packages/sphinx/util/rst.py:58
/Users/chrisjsewell/Documents/GitHub/aiida_core_develop/.tox/py38-django/lib/python3.8/site-packages/sphinx/util/rst.py:58: DeprecationWarning: 'environmentfilter' is renamed to 'pass_environment', the old name will be removed in Jinja 3.1.
def heading(env: Environment, text: str, level: int = 1) -> str:
.tox/py38-django/lib/python3.8/site-packages/sphinx/jinja2glue.py:106
/Users/chrisjsewell/Documents/GitHub/aiida_core_develop/.tox/py38-django/lib/python3.8/site-packages/sphinx/jinja2glue.py:106: DeprecationWarning: 'contextfunction' is renamed to 'pass_context', the old name will be removed in Jinja 3.1.
def warning(context: Dict, message: str, *args: Any, **kwargs: Any) -> str:
tests/manage/test_profile_access.py::test_access_control
/Users/chrisjsewell/Documents/GitHub/aiida_core_develop/aiida/manage/configuration/settings.py:61: UserWarning: Creating AiiDA configuration folder `/var/folders/t2/xbl15_3n4tsb1vr_ccmmtmbr0000gn/T/tmpz0_m7fz3/.aiida`.
warnings.warn(f'Creating AiiDA configuration folder `{path}`.')
-- Docs: https://docs.pytest.org/en/stable/warnings.html
=============================================================================================== slowest 50 durations ===============================================================================================
10.20s call tests/manage/test_profile_access.py::test_access_control
6.54s setup tests/manage/test_profile_access.py::test_access_control
0.22s teardown tests/manage/test_profile_access.py::test_access_control
============================================================================================= short test summary info ==============================================================================================
FAILED tests/manage/test_profile_access.py::test_access_control - RuntimeError: Process loading was too slow!
========================================================================================== 1 failed, 5 warnings in 17.37s ==========================================================================================
/Users/chrisjsewell/Documents/GitHub/aiida_core_develop/.tox/py38-django/lib/python3.8/subprocess.py:946: ResourceWarning: subprocess 64404 is still running
sys:1: ResourceWarning: unclosed file <_io.BufferedReader name=22>
ERROR: InvocationError for command /Users/chrisjsewell/Documents/GitHub/aiida_core_develop/.tox/py38-django/bin/pytest tests/manage/test_profile_access.py::test_access_control (exited with code 1)
_____________________________________________________________________________________________________ summary ______________________________________________________________________________________________________
ERROR: py38-django: commands failed
(b
If I I change check_count == 100 to check_count == 1000, the I get:
FAILED tests/manage/test_profile_access.py::test_access_control - AssertionError: assert '65487.pid' in ['65417.pid']
FYI, I checked this is not a tox specific issue, i.e. the same issue is present when directly calling pytest
The first part of the problem seems to be that the particular setup takes a bit too much (more than 10 seconds) in launching a subprocess and/or loading the AiiDA profile. I will try to replace the tests that use the MockProcess.
The second part is a bit more difficult and it might be harder to debug without access to an environment where I can reproduce it. You are running these tests inside a docker container, right? Can I get the parameters of it?
cheers
You are running these tests inside a docker container, right?
no just locally on my macbook
Uhm, ok, then I think before doing any changes to the tests it might be better to try to figure out what is happening. Because to remove the MockProcess I would need to monkeypatch the os.getpid() calls or something like this and might end up hiding some problem of incompatibilities that is triggering here.
Can you replace the test_access_control function with this and run with pytest -s?
def test_access_control(profile_access_manager):
accessing_process = MockProcess(profile_access_manager.profile)
import os
state0 = os.listdir(profile_access_manager._dirpath_records)
accessing_pid = accessing_process.start()
state1 = os.listdir(profile_access_manager._dirpath_records)
assert profile_access_manager.is_active()
accessing_process.stop()
process_file = str(accessing_pid) + '.pid'
print('\n\n')
print(os.getpid(), accessing_pid)
print(state0)
print(state1)
print(os.listdir(profile_access_manager._dirpath_records))
print('\n\n')
tracking_files = [filepath.name for filepath in profile_access_manager._get_tracking_files('.pid')]
assert process_file in tracking_files
(with also check_count == 1000)
$ pytest tests/manage/test_profile_access.py::test_access_control
=============================================================================================== test session starts ================================================================================================
platform darwin -- Python 3.8.12, pytest-6.2.5, py-1.11.0, pluggy-1.0.0
benchmark: 3.4.1 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000)
rootdir: /Users/chrisjsewell/Documents/GitHub/aiida_core_develop, configfile: pyproject.toml
plugins: asyncio-0.16.0, benchmark-3.4.1, datadir-1.3.1, rerunfailures-9.1.1, regressions-2.2.0, cov-2.10.1, timeout-1.4.2
collected 1 item
tests/manage/test_profile_access.py F [100%]
===================================================================================================== FAILURES =====================================================================================================
_______________________________________________________________________________________________ test_access_control ________________________________________________________________________________________________
profile_access_manager = <aiida.manage.profile_access.ProfileAccessManager object at 0x7f883b4cf670>
def test_access_control(profile_access_manager):
accessing_process = MockProcess(profile_access_manager.profile)
import os
state0 = os.listdir(profile_access_manager._dirpath_records)
accessing_pid = accessing_process.start()
state1 = os.listdir(profile_access_manager._dirpath_records)
assert profile_access_manager.is_active()
accessing_process.stop()
process_file = str(accessing_pid) + '.pid'
print('\n\n')
print(os.getpid(), accessing_pid)
print(state0)
print(state1)
print(os.listdir(profile_access_manager._dirpath_records))
print('\n\n')
tracking_files = [filepath.name for filepath in profile_access_manager._get_tracking_files('.pid')]
> assert process_file in tracking_files
E AssertionError: assert '87749.pid' in ['87502.pid', '87676.pid', '72942.pid']
tests/manage/test_profile_access.py:266: AssertionError
------------------------------------------------------------------------------------------------ Captured log setup ------------------------------------------------------------------------------------------------
DEBUG pgsu:__init__.py:141 Trying to connect via "psycopg2"...
----------------------------------------------------------------------------------------------- Captured stdout call -----------------------------------------------------------------------------------------------
87676 87749
['87502.pid', '87676.pid', '72942.pid']
['87502.pid', '87676.pid', '72942.pid']
['87502.pid', '87676.pid', '72942.pid']
================================================================================================= warnings summary =================================================================================================
aiida/manage/tests/unittest_classes.py:23
/Users/chrisjsewell/Documents/GitHub/aiida_core_develop/aiida/manage/tests/unittest_classes.py:23: AiidaDeprecationWarning: This module has been deprecated and will be removed soon. Please use the `pytest` fixtures instead.
See https://github.com/aiidateam/aiida-core/wiki/AiiDA-2.0-plugin-migration-guide#unit-tests
warnings.warn( # pylint: disable=no-member
.tox/py38-pre-commit/lib/python3.8/site-packages/sphinx/util/docutils.py:45
/Users/chrisjsewell/Documents/GitHub/aiida_core_develop/.tox/py38-pre-commit/lib/python3.8/site-packages/sphinx/util/docutils.py:45: DeprecationWarning: distutils Version classes are deprecated. Use packaging.version instead.
__version_info__ = tuple(LooseVersion(docutils.__version__).version)
.tox/py38-pre-commit/lib/python3.8/site-packages/sphinx/util/rst.py:58
/Users/chrisjsewell/Documents/GitHub/aiida_core_develop/.tox/py38-pre-commit/lib/python3.8/site-packages/sphinx/util/rst.py:58: DeprecationWarning: 'environmentfilter' is renamed to 'pass_environment', the old name will be removed in Jinja 3.1.
def heading(env: Environment, text: str, level: int = 1) -> str:
.tox/py38-pre-commit/lib/python3.8/site-packages/sphinx/jinja2glue.py:106
/Users/chrisjsewell/Documents/GitHub/aiida_core_develop/.tox/py38-pre-commit/lib/python3.8/site-packages/sphinx/jinja2glue.py:106: DeprecationWarning: 'contextfunction' is renamed to 'pass_context', the old name will be removed in Jinja 3.1.
def warning(context: Dict, message: str, *args: Any, **kwargs: Any) -> str:
tests/manage/test_profile_access.py::test_access_control
/Users/chrisjsewell/Documents/GitHub/aiida_core_develop/aiida/manage/configuration/settings.py:61: UserWarning: Creating AiiDA configuration folder `/var/folders/t2/xbl15_3n4tsb1vr_ccmmtmbr0000gn/T/tmpw3pvw3ou/.aiida`.
warnings.warn(f'Creating AiiDA configuration folder `{path}`.')
-- Docs: https://docs.pytest.org/en/stable/warnings.html
=============================================================================================== slowest 50 durations ===============================================================================================
10.19s call tests/manage/test_profile_access.py::test_access_control
5.88s setup tests/manage/test_profile_access.py::test_access_control
0.26s teardown tests/manage/test_profile_access.py::test_access_control
============================================================================================= short test summary info ==============================================================================================
FAILED tests/manage/test_profile_access.py::test_access_control - AssertionError: assert '87749.pid' in ['87502.pid', '87676.pid', '72942.pid']
========================================================================================== 1 failed, 5 warnings in 16.73s ==========================================================================================
Just for reference, this is how long it is taking in my own setup:
3.90s call tests/manage/test_profile_access.py::test_lock
1.83s call tests/manage/test_profile_access.py::test_access_control
1.56s call tests/manage/test_profile_access.py::test_request_access_errors[was locked while]
1.55s call tests/manage/test_profile_access.py::test_request_access_errors[is being locked]
1.28s setup tests/manage/test_profile_access.py::test_get_tracking_files
0.02s call tests/manage/test_profile_access.py::test_get_tracking_files
0.02s call tests/manage/test_profile_access.py::test_clear_stale_pid_files
0.01s call tests/manage/test_profile_access.py::test_clear_locks
0.01s call tests/manage/test_profile_access.py::test_raise_methods
In the github machine it is taking a bit more, but it is still less than 10 seconds and it is still not the longest tests:
178.56s call tests/cmdline/commands/test_code.py::test_code_setup_local_duplicate_full_label_interactive[sleep 1; vim -cwq]
31.88s call tests/backends/aiida_sqlalchemy/migrations/test_all_basic.py::test_all_empty_migrations
22.18s call tests/cmdline/commands/test_run.py::TestAutoGroups::test_autogroup_filter_class
16.99s call tests/tools/archive/orm/test_links.py::test_high_level_workflow_links
15.66s call tests/cmdline/commands/test_data.py::TestVerdiData::test_reachable
10.16s call tests/tools/archive/orm/test_links.py::test_complex_workflow_graph_export_sets
8.57s call tests/tools/archive/orm/test_links.py::test_link_flags
7.64s call tests/cmdline/commands/test_computer.py::TestVerdiComputerConfigure::test_reachable
6.69s call tests/transports/test_all_plugins.py::TestExecuteCommandWait::test_transfer_big_stdout
6.49s call tests/test_nodes.py::TestNodeDeletion::test_delete_cases
6.17s call tests/cmdline/commands/test_code.py::test_code_setup_remote_duplicate_full_label_interactive[sleep 1; vim -cwq]
6.17s call tests/cmdline/commands/test_daemon.py::test_daemon_restart
6.15s call tests/cmdline/commands/test_computer.py::test_interactive[sleep 1; vim -cwq]
5.87s call tests/manage/test_profile_access.py::test_lock
(...)
As a recap from what we managed to figure out so far: we found that the second error was unrelated and so the only problem now is why is it taking so long to launch the subprocess (if it can do it at all). Apparently subprocess works with no problem, at least when called directly from the python interpreter, so this could be either (1) the pytest-subprocess interface acting out or (2) something else in the specific MockProcess class gets triggered in OSX.
For testing (1) I already sent you a script via slack that you could try running on pytest to see if it still has problems without the class. For testing (2), you could try to put the following script in the aiida-core/tests/manage folder and run it with verdi run to see if it raises:
import test_profile_access
from aiida.manage.manager import get_manager
aiida_profile = get_manager().get_profile()
test_process = test_profile_access.MockProcess(aiida_profile)
process_id = test_process.start()
print(f'Now running process {process_id}')
test_process.stop()
Let me know how it goes.
@ramirezfranciscof do you want to close https://github.com/aiidateam/aiida-core/pull/5325 and create your own, so we can see if it is replicate with macos on the CI?
Yes sure, I could try that, I may have a bit more time after thursday to start on this. I have never created any CI workflow before so I may have to bother you with some questions, but I would welcome the exercise.