tests/manage/test_profile_access.py::test_access_control consistently fails (on OSX)

chrisjsewell commented 2 years ago

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']

chrisjsewell commented 2 years ago

FYI, I checked this is not a tox specific issue, i.e. the same issue is present when directly calling pytest

ramirezfranciscof commented 2 years ago

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?

chrisjsewell commented 2 years ago

cheers

You are running these tests inside a docker container, right?

no just locally on my macbook

ramirezfranciscof commented 2 years ago

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

chrisjsewell commented 2 years ago

(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 ==========================================================================================

ramirezfranciscof commented 2 years ago

Mmm, moving to slack, will report back when we find the problem.

ramirezfranciscof commented 2 years ago

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
(...)

ramirezfranciscof commented 2 years ago

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.

chrisjsewell commented 2 years ago

@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?

ramirezfranciscof commented 2 years ago

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.

chrisjsewell commented 2 years ago

yeh no worries 👍

aiidateam / aiida-core

tests/manage/test_profile_access.py::test_access_control consistently fails (on OSX) #5323