Current git HEAD tests fail on FreeBSD 14 / Python 3.11.9: test_python_factory_invalid_callable_value

[thresheek]

When built with ./configure && ./configure python --config=python3-config && make, Unit currently fails the test on FreeBSD 14, with Python 3.11.9. No other tests fail.

freebsd% python3 -m pytest test/test_python_factory.py -k test_python_factory_invalid_callable_value
error: no such command: `component`

	View all installed commands with `cargo --list`
	Find a package to install `component` with `cargo search cargo-component`
================================================================================================================ test session starts ================================================================================================================
platform freebsd14 -- Python 3.11.9, pytest-8.1.1, pluggy-1.5.0 -- /usr/local/bin/python3
cachedir: .pytest_cache
rootdir: /home/thresh/unit/test
configfile: pytest.ini
collected 3 items / 2 deselected / 1 selected

test/test_python_factory.py::test_python_factory_invalid_callable_value[3.11.9] PASSEDPath to unit.log:
/tmp/unit-test-50st51c0/unit.log

2024/09/06 02:25:35 [warn] 12023#100112 Unit is running unprivileged, then it cannot use arbitrary user and group.
2024/09/06 02:25:35 [info] 12023#100112 unit 1.33.0 started
2024/09/06 02:25:35 [info] 12024#100171 discovery started
2024/09/06 02:25:35 [notice] 12024#100171 module: python 3.11.9 "/home/thresh/unit/build/lib/unit/modules/python3.unit.so"
2024/09/06 02:25:35 [info] 12023#100112 controller started
2024/09/06 02:25:35 [notice] 12023#100112 process 12024 exited with code 0
2024/09/06 02:25:35 [info] 12026#100495 router started
2024/09/06 02:25:35 [error] 12025#100089 abstract unix domain sockets are not supported
2024/09/06 02:25:35 [info] 12039#100399 "targets" prototype started
2024/09/06 02:25:35 [info] 12040#100263 "targets" application started
2024/09/06 02:25:35 [alert] 12040#100263 factory "wsgi_factory_returning_invalid_callable" in module "wsgi" did not return callable object
2024/09/06 02:25:35 [notice] 12039#100399 app process 12040 exited with code 1
2024/09/06 02:25:35 [warn] 12026#100495 failed to start application "targets"
2024/09/06 02:25:35 [alert] 12026#100495 failed to apply new conf
2024/09/06 02:25:35 [notice] 12023#100112 process 12039 exited with code 0
2024/09/06 02:25:35 [info] 12041#100263 "targets" prototype started
2024/09/06 02:25:35 [info] 12042#100226 "targets" application started
2024/09/06 02:25:35 [alert] 12042#100226 factory "wsgi_invalid_callable" in module "wsgi" can not be called to fetch callable
Fatal Python error: none_dealloc: deallocating None: bug likely caused by a refcount error in a C extension
Python runtime state: finalizing (tstate=0x0000000826aff810)

Current thread 0x00002fb3dd812000 (most recent call first):
  <no Python frame>
2024/09/06 02:25:36 [alert] 12041#100263 app process 12042 exited on signal 6 (core dumped)
2024/09/06 02:25:36 [warn] 12026#100495 failed to start application "targets"
2024/09/06 02:25:36 [alert] 12026#100495 failed to apply new conf
2024/09/06 02:25:36 [notice] 12023#100112 process 12041 exited with code 0

test/test_python_factory.py::test_python_factory_invalid_callable_value[3.11.9] ERROR

====================================================================================================================== ERRORS =======================================================================================================================
______________________________________________________________________________________ ERROR at teardown of test_python_factory_invalid_callable_value[3.11.9] ______________________________________________________________________________________

request = <SubRequest 'run' for <Function test_python_factory_invalid_callable_value[3.11.9]>>

    @pytest.fixture(autouse=True)
    def run(request):
        unit = unit_run()

        option.skip_alerts = [
            r'read signalfd\(4\) failed',
            r'sendmsg.+failed',
            r'recvmsg.+failed',
        ]
        option.skip_sanitizer = False

        _fds_info['main']['skip'] = False
        _fds_info['router']['skip'] = False
        _fds_info['controller']['skip'] = False

        yield

        # stop unit

        error_stop_unit = unit_stop()
        error_stop_processes = stop_processes()

        # prepare log

        with Log.open() as f:
            log = f.read()
            Log.set_pos(f.tell())

        if not option.save_log and option.restart:
            shutil.rmtree(unit['temp_dir'])
            Log.set_pos(0)

        # clean temp_dir before the next test

        if not option.restart:
            _clear_conf(log=log)
            _clear_temp_dir()

        # check descriptors

        _check_fds(log=log)

        # check processes id's and amount

        _check_processes()

        # print unit.log in case of error

        if hasattr(request.node, 'rep_call') and request.node.rep_call.failed:
            Log.print_log(log)

        if error_stop_unit or error_stop_processes:
            Log.print_log(log)

        # check unit.log for errors

        assert error_stop_unit is None, 'stop unit'
        assert error_stop_processes is None, 'stop processes'

>       Log.check_alerts(log=log)

test/conftest.py:261:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
test/unit/log.py:17: in inner_function
    raise exception
test/unit/log.py:14: in inner_function
    func(*args, **kwargs)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

log = '2024/09/06 02:25:35 [warn] 12023#100112 Unit is running unprivileged, then it cannot use arbitrary user and group.\n2...t] 12026#100495 failed to apply new conf\n2024/09/06 02:25:36 [notice] 12023#100112 process 12041 exited with code 0\n'

    @staticmethod
    @print_log_on_assert
    def check_alerts(log=None):
        if log is None:
            log = Log.read()

        found = False
        alerts = re.findall(r'.+\[alert\].+', log)

        if alerts:
            found = True

            if option.detailed:
                print('\nAll alerts/sanitizer errors found in log:')
                _ = [print(alert) for alert in alerts]

        if option.skip_alerts:
            for skip in option.skip_alerts:
                alerts = [al for al in alerts if re.search(skip, al) is None]

>       assert not alerts, 'alert(s)'
E       AssertionError: alert(s)

test/unit/log.py:45: AssertionError
============================================================================================================== short test summary info ==============================================================================================================
ERROR test/test_python_factory.py::test_python_factory_invalid_callable_value[3.11.9] - AssertionError: alert(s)
===================================================================================================== 1 passed, 2 deselected, 1 error in 1.02s ======================================================================================================

[ac000]

Hmm, I have a vague recollection of hitting this before and it was something particular to this version of Python...

[callahad]

Bears further investigation, but if we're only seeing it on that specific FreeBSD / Python version combination, not a release blocker.

[ac000]

I believe it's a bug in that version of Python.

[callahad]

Can we verify that by getting the tests to pass on any newer version of FreeBSD + Python?

[thresheek]

It's currently the latest version of Python that is available on FreeBSD.

The test does succeed with 3.10 which is also available:

test/test_python_factory.py::test_python_factory_invalid_callable_value[3.10.14] PASSED

[ac000]

Yeah, I wouldn't worry about it.

That failing test is for the new Python Application Factory thing, and in this case we are deliberately doing something wrong.

[ac000]

@thresheek

You could try this patch from #1420

diff --git ./src/python/nxt_python.c ./src/python/nxt_python.c
index 7bbf3d49..a1d4444c 100644
--- ./src/python/nxt_python.c
+++ ./src/python/nxt_python.c
@@ -258,6 +258,8 @@ nxt_python_start(nxt_task_t *task, nxt_process_data_t *data)
         goto fail;
     }
 
+    Py_INCREF(nxt_py_stderr_flush);
+
     if (nxt_slow_path(nxt_python_set_path(task, c->path) != NXT_OK)) {
         goto fail;
     }