k-wave-python icon indicating copy to clipboard operation
k-wave-python copied to clipboard

[BUG] Logging output error for logging.DEBUG

Open waltsims opened this issue 1 year ago • 4 comments

To Reproduce Add the following lines to tests/test_checks.py

import logging
logging.basicConfig(level=logging.DEBUG)

The file produces many logging errors

Expected behavior logging should not throw errors

waltsims avatar Jun 23 '24 03:06 waltsims

I cannot reproduce this. Here is what I see:

=========================================================================================== 2 passed, 2 skipped in 2.49s ===========================================================================================
(env_k) faridyagubbayli@Mac tests % pytest -s -v -o log_cli=True test_checks.py
=============================================================================================== test session starts ================================================================================================
platform darwin -- Python 3.11.9, pytest-8.2.2, pluggy-1.5.0 -- ~/miniconda3/envs/env_k/bin/python
cachedir: .pytest_cache
rootdir: ..../k-wave-python
configfile: pyproject.toml
plugins: jaxtyping-0.2.30, typeguard-2.13.3
collected 4 items                                                                                                                                                                                                  

test_checks.py::TestUltrasoundSimulation::test_simulation_cpu_none PASSED
test_checks.py::TestUltrasoundSimulation::test_simulation_cpu_omp PASSED
test_checks.py::TestUltrasoundSimulation::test_simulation_gpu_cuda SKIPPED (GPU simulations are currently not supported on MacOS)
test_checks.py::TestUltrasoundSimulation::test_simulation_gpu_none SKIPPED (GPU simulations are currently not supported on MacOS)

=========================================================================================== 2 passed, 2 skipped in 2.62s ===========================================================================================
(

Can this be happening only for the GPU simulations?

faridyagubbayli avatar Jul 02 '24 07:07 faridyagubbayli

Tried on Linux with a GPU and still don't see any logging errors.

(env_k) **@***:~/projects/k/k-wave-python/tests$ pytest -s -v -o log_cli=True test_checks.py 
================================================================================================ test session starts =================================================================================================
platform linux -- Python 3.11.9, pytest-8.2.2, pluggy-1.5.0 -- ~miniconda3/envs/env_k/bin/python
cachedir: .pytest_cache
rootdir: .../k-wave-python
configfile: pyproject.toml
plugins: jaxtyping-0.2.30, typeguard-2.13.3
collected 4 items                                                                                                                                                                                                    

test_checks.py::TestUltrasoundSimulation::test_simulation_cpu_none PASSED
test_checks.py::TestUltrasoundSimulation::test_simulation_cpu_omp PASSED
test_checks.py::TestUltrasoundSimulation::test_simulation_gpu_cuda PASSED
test_checks.py::TestUltrasoundSimulation::test_simulation_gpu_none PASSED

================================================================================================= 4 passed in 7.72s ==================================================================================================

@waltsims can you share the errors you see?

faridyagubbayli avatar Jul 02 '24 08:07 faridyagubbayli

You have to add the lines above to the test file to turn on DEBUG logging:

============================= test session starts ==============================
platform darwin -- Python 3.9.13, pytest-7.1.2, pluggy-1.0.0
rootdir: /Users/walters/git/k-wave-python, configfile: pyproject.toml
plugins: anyio-3.6.1, pyfakefs-5.5.0, jaxtyping-0.2.30, typeguard-2.13.3, cov-4.0.0
collected 4 items

tests/test_checks.py FFss                                                [100%]

=================================== FAILURES ===================================
______________ TestUltrasoundSimulation.test_simulation_cpu_none _______________

self = <tests.test_checks.TestUltrasoundSimulation testMethod=test_simulation_cpu_none>
mock_run_simulation = <MagicMock name='run_simulation' id='13284403232'>

    @patch("kwave.kspaceFirstOrder2D.Executor.run_simulation")
    def test_simulation_cpu_none(self, mock_run_simulation):
        mock_run_simulation.return_value = None
>       self._test_simulation(mock_run_simulation, is_gpu_simulation=False, binary_name=None)

tests/test_checks.py:120: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
tests/test_checks.py:140: in _test_simulation
    self.run_simulation(is_gpu_simulation=is_gpu_simulation, binary_name=binary_name)
tests/test_checks.py:108: in run_simulation
    _ = kspaceFirstOrder2D(
kwave/kspaceFirstOrder2D.py:297: in kspaceFirstOrder2D
    k_sim.input_checking("kspaceFirstOrder2D")
kwave/kWaveSimulation.py:494: in input_checking
    self.c_ref, self.c_ref_compression, self.c_ref_shear = set_sound_speed_ref(self.medium, opt.simulation_type)
kwave/kWaveSimulation_helper/set_sound_speed_ref.py:19: in set_sound_speed_ref
    return get_ordinary_sound_speed_ref(medium)
kwave/kWaveSimulation_helper/set_sound_speed_ref.py:38: in get_ordinary_sound_speed_ref
    c_ref = _get_sound_speed_ref(medium.sound_speed_ref, medium.sound_speed)
kwave/kWaveSimulation_helper/set_sound_speed_ref.py:89: in _get_sound_speed_ref
    logging.log(logging.INFO, "  reference sound speed: ", c_ref, "m/s")
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:2117: in log
    root.log(level, msg, *args, **kwargs)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1512: in log
    self._log(level, msg, args, **kwargs)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1589: in _log
    self.handle(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1599: in handle
    self.callHandlers(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1661: in callHandlers
    hdlr.handle(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:952: in handle
    self.emit(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/logging.py:342: in emit
    super().emit(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1091: in emit
    self.handleError(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1083: in emit
    msg = self.format(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:927: in format
    return fmt.format(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/logging.py:113: in format
    return super().format(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:663: in format
    record.message = record.getMessage()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <LogRecord: root, 20, /Users/walters/git/k-wave-python/kwave/kWaveSimulation_helper/set_sound_speed_ref.py, 89, "  reference sound speed: ">

    def getMessage(self):
        """
        Return the message for this LogRecord.
    
        Return the message for this LogRecord after merging any user-supplied
        arguments with the message.
        """
        msg = str(self.msg)
        if self.args:
>           msg = msg % self.args
E           TypeError: not all arguments converted during string formatting

/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:367: TypeError
----------------------------- Captured stderr call -----------------------------
INFO:root:  start time: 02-Jul-2024-10-01-34
INFO:root:Running k-Wave simulation...
INFO:root:  start time: 02-Jul-2024-10-01-34
--- Logging error ---
Traceback (most recent call last):
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py", line 1083, in emit
    msg = self.format(record)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py", line 927, in format
    return fmt.format(record)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py", line 663, in format
    record.message = record.getMessage()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py", line 367, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/Users/walters/git/k-wave-python/tests/test_checks.py", line 145, in <module>
    pytest.main([__file__])
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/config/__init__.py", line 164, in main
    ret: Union[ExitCode, int] = config.hook.pytest_cmdline_main(
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/main.py", line 315, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/main.py", line 268, in wrap_session
    session.exitstatus = doit(config, session) or 0
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/main.py", line 322, in _main
    config.hook.pytest_runtestloop(session=session)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/main.py", line 347, in pytest_runtestloop
    item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 111, in pytest_runtest_protocol
    runtestprotocol(item, nextitem=nextitem)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 130, in runtestprotocol
    reports.append(call_and_report(item, "call", log))
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 219, in call_and_report
    call = call_runtest_hook(item, when, **kwds)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 258, in call_runtest_hook
    return CallInfo.from_call(
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 338, in from_call
    result: Optional[TResult] = func()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 259, in <lambda>
    lambda: ihook(item=item, **kwds), when=when, reraise=reraise
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 166, in pytest_runtest_call
    item.runtest()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/unittest.py", line 327, in runtest
    self._testcase(result=self)  # type: ignore[arg-type]
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/unittest/case.py", line 651, in __call__
    return self.run(*args, **kwds)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/unittest/case.py", line 592, in run
    self._callTestMethod(testMethod)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/unittest/case.py", line 550, in _callTestMethod
    method()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/unittest/mock.py", line 1336, in patched
    return func(*newargs, **newkeywargs)
  File "/Users/walters/git/k-wave-python/tests/test_checks.py", line 120, in test_simulation_cpu_none
    self._test_simulation(mock_run_simulation, is_gpu_simulation=False, binary_name=None)
  File "/Users/walters/git/k-wave-python/tests/test_checks.py", line 140, in _test_simulation
    self.run_simulation(is_gpu_simulation=is_gpu_simulation, binary_name=binary_name)
  File "/Users/walters/git/k-wave-python/tests/test_checks.py", line 108, in run_simulation
    _ = kspaceFirstOrder2D(
  File "/Users/walters/git/k-wave-python/kwave/kspaceFirstOrder2D.py", line 297, in kspaceFirstOrder2D
    k_sim.input_checking("kspaceFirstOrder2D")
  File "/Users/walters/git/k-wave-python/kwave/kWaveSimulation.py", line 494, in input_checking
    self.c_ref, self.c_ref_compression, self.c_ref_shear = set_sound_speed_ref(self.medium, opt.simulation_type)
  File "/Users/walters/git/k-wave-python/kwave/kWaveSimulation_helper/set_sound_speed_ref.py", line 19, in set_sound_speed_ref
    return get_ordinary_sound_speed_ref(medium)
  File "/Users/walters/git/k-wave-python/kwave/kWaveSimulation_helper/set_sound_speed_ref.py", line 38, in get_ordinary_sound_speed_ref
    c_ref = _get_sound_speed_ref(medium.sound_speed_ref, medium.sound_speed)
  File "/Users/walters/git/k-wave-python/kwave/kWaveSimulation_helper/set_sound_speed_ref.py", line 89, in _get_sound_speed_ref
    logging.log(logging.INFO, "  reference sound speed: ", c_ref, "m/s")
Message: '  reference sound speed: '
Arguments: (1000, 'm/s')
------------------------------ Captured log call -------------------------------
INFO     root:kWaveSimulation.py:107   start time: 02-Jul-2024-10-01-34
INFO     root:kWaveSimulation.py:553 Running k-Wave simulation...
INFO     root:kWaveSimulation.py:554   start time: 02-Jul-2024-10-01-34
_______________ TestUltrasoundSimulation.test_simulation_cpu_omp _______________

self = <tests.test_checks.TestUltrasoundSimulation testMethod=test_simulation_cpu_omp>
mock_run_simulation = <MagicMock name='run_simulation' id='13527565984'>

    @patch("kwave.kspaceFirstOrder2D.Executor.run_simulation")
    def test_simulation_cpu_omp(self, mock_run_simulation):
        mock_run_simulation.return_value = None
>       self._test_simulation(mock_run_simulation, is_gpu_simulation=False, binary_name="kspaceFirstOrder-OMP")

tests/test_checks.py:137: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
tests/test_checks.py:140: in _test_simulation
    self.run_simulation(is_gpu_simulation=is_gpu_simulation, binary_name=binary_name)
tests/test_checks.py:108: in run_simulation
    _ = kspaceFirstOrder2D(
kwave/kspaceFirstOrder2D.py:297: in kspaceFirstOrder2D
    k_sim.input_checking("kspaceFirstOrder2D")
kwave/kWaveSimulation.py:494: in input_checking
    self.c_ref, self.c_ref_compression, self.c_ref_shear = set_sound_speed_ref(self.medium, opt.simulation_type)
kwave/kWaveSimulation_helper/set_sound_speed_ref.py:19: in set_sound_speed_ref
    return get_ordinary_sound_speed_ref(medium)
kwave/kWaveSimulation_helper/set_sound_speed_ref.py:38: in get_ordinary_sound_speed_ref
    c_ref = _get_sound_speed_ref(medium.sound_speed_ref, medium.sound_speed)
kwave/kWaveSimulation_helper/set_sound_speed_ref.py:89: in _get_sound_speed_ref
    logging.log(logging.INFO, "  reference sound speed: ", c_ref, "m/s")
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:2117: in log
    root.log(level, msg, *args, **kwargs)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1512: in log
    self._log(level, msg, args, **kwargs)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1589: in _log
    self.handle(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1599: in handle
    self.callHandlers(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1661: in callHandlers
    hdlr.handle(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:952: in handle
    self.emit(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/logging.py:342: in emit
    super().emit(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1091: in emit
    self.handleError(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:1083: in emit
    msg = self.format(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:927: in format
    return fmt.format(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/logging.py:113: in format
    return super().format(record)
/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:663: in format
    record.message = record.getMessage()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <LogRecord: root, 20, /Users/walters/git/k-wave-python/kwave/kWaveSimulation_helper/set_sound_speed_ref.py, 89, "  reference sound speed: ">

    def getMessage(self):
        """
        Return the message for this LogRecord.
    
        Return the message for this LogRecord after merging any user-supplied
        arguments with the message.
        """
        msg = str(self.msg)
        if self.args:
>           msg = msg % self.args
E           TypeError: not all arguments converted during string formatting

/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py:367: TypeError
----------------------------- Captured stderr call -----------------------------
INFO:root:  start time: 02-Jul-2024-10-01-34
INFO:root:Running k-Wave simulation...
INFO:root:  start time: 02-Jul-2024-10-01-34
--- Logging error ---
Traceback (most recent call last):
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py", line 1083, in emit
    msg = self.format(record)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py", line 927, in format
    return fmt.format(record)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py", line 663, in format
    record.message = record.getMessage()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/logging/__init__.py", line 367, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/Users/walters/git/k-wave-python/tests/test_checks.py", line 145, in <module>
    pytest.main([__file__])
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/config/__init__.py", line 164, in main
    ret: Union[ExitCode, int] = config.hook.pytest_cmdline_main(
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/main.py", line 315, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/main.py", line 268, in wrap_session
    session.exitstatus = doit(config, session) or 0
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/main.py", line 322, in _main
    config.hook.pytest_runtestloop(session=session)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/main.py", line 347, in pytest_runtestloop
    item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 111, in pytest_runtest_protocol
    runtestprotocol(item, nextitem=nextitem)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 130, in runtestprotocol
    reports.append(call_and_report(item, "call", log))
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 219, in call_and_report
    call = call_runtest_hook(item, when, **kwds)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 258, in call_runtest_hook
    return CallInfo.from_call(
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 338, in from_call
    result: Optional[TResult] = func()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 259, in <lambda>
    lambda: ihook(item=item, **kwds), when=when, reraise=reraise
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/runner.py", line 166, in pytest_runtest_call
    item.runtest()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/unittest.py", line 327, in runtest
    self._testcase(result=self)  # type: ignore[arg-type]
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/unittest/case.py", line 651, in __call__
    return self.run(*args, **kwds)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/unittest/case.py", line 592, in run
    self._callTestMethod(testMethod)
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/unittest/case.py", line 550, in _callTestMethod
    method()
  File "/opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/unittest/mock.py", line 1336, in patched
    return func(*newargs, **newkeywargs)
  File "/Users/walters/git/k-wave-python/tests/test_checks.py", line 137, in test_simulation_cpu_omp
    self._test_simulation(mock_run_simulation, is_gpu_simulation=False, binary_name="kspaceFirstOrder-OMP")
  File "/Users/walters/git/k-wave-python/tests/test_checks.py", line 140, in _test_simulation
    self.run_simulation(is_gpu_simulation=is_gpu_simulation, binary_name=binary_name)
  File "/Users/walters/git/k-wave-python/tests/test_checks.py", line 108, in run_simulation
    _ = kspaceFirstOrder2D(
  File "/Users/walters/git/k-wave-python/kwave/kspaceFirstOrder2D.py", line 297, in kspaceFirstOrder2D
    k_sim.input_checking("kspaceFirstOrder2D")
  File "/Users/walters/git/k-wave-python/kwave/kWaveSimulation.py", line 494, in input_checking
    self.c_ref, self.c_ref_compression, self.c_ref_shear = set_sound_speed_ref(self.medium, opt.simulation_type)
  File "/Users/walters/git/k-wave-python/kwave/kWaveSimulation_helper/set_sound_speed_ref.py", line 19, in set_sound_speed_ref
    return get_ordinary_sound_speed_ref(medium)
  File "/Users/walters/git/k-wave-python/kwave/kWaveSimulation_helper/set_sound_speed_ref.py", line 38, in get_ordinary_sound_speed_ref
    c_ref = _get_sound_speed_ref(medium.sound_speed_ref, medium.sound_speed)
  File "/Users/walters/git/k-wave-python/kwave/kWaveSimulation_helper/set_sound_speed_ref.py", line 89, in _get_sound_speed_ref
    logging.log(logging.INFO, "  reference sound speed: ", c_ref, "m/s")
Message: '  reference sound speed: '
Arguments: (1000, 'm/s')
------------------------------ Captured log call -------------------------------
INFO     root:kWaveSimulation.py:107   start time: 02-Jul-2024-10-01-34
INFO     root:kWaveSimulation.py:553 Running k-Wave simulation...
INFO     root:kWaveSimulation.py:554   start time: 02-Jul-2024-10-01-34
=============================== warnings summary ===============================
../../../../opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/config/__init__.py:1129
  /opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/config/__init__.py:1129: PytestAssertRewriteWarning: Module already imported so cannot be rewritten: jaxtyping
    self._mark_plugins_for_rewrite(hook)

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
=========================== short test summary info ============================
FAILED tests/test_checks.py::TestUltrasoundSimulation::test_simulation_cpu_none
FAILED tests/test_checks.py::TestUltrasoundSimulation::test_simulation_cpu_omp
=================== 2 failed, 2 skipped, 1 warning in 0.53s ====================

Without adding those lines to the test file, I get the same output as you:

============================= test session starts ==============================
platform darwin -- Python 3.9.13, pytest-7.1.2, pluggy-1.0.0
rootdir: /Users/walters/git/k-wave-python, configfile: pyproject.toml
plugins: anyio-3.6.1, pyfakefs-5.5.0, jaxtyping-0.2.30, typeguard-2.13.3, cov-4.0.0
collected 4 items

tests/test_checks.py ..ss                                                [100%]

=============================== warnings summary ===============================
../../../../opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/config/__init__.py:1129
  /opt/homebrew/Caskroom/miniforge/base/envs/k-wave-python/lib/python3.9/site-packages/_pytest/config/__init__.py:1129: PytestAssertRewriteWarning: Module already imported so cannot be rewritten: jaxtyping
    self._mark_plugins_for_rewrite(hook)

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
=================== 2 passed, 2 skipped, 1 warning in 2.69s ====================

waltsims avatar Jul 02 '24 17:07 waltsims

@waltsims I tried to reproduce this with Python 3.9 but still not seeing any warning. I have the logging config lines from your instructions. Maybe this is somehow specific to your environment?

faridyagubbayli avatar Jul 09 '24 09:07 faridyagubbayli

Taking this over since @faridyagubbayli cannot reproduce it.

waltsims avatar Jul 16 '24 18:07 waltsims