Tim Jenness added a comment - 09/Jul/21 9:28 PM In case you haven't got the stack trace: $ python tests/test_log.py .....root WARN: lsst.log warning message that will not be forwarded to Python .Fatal Python error: PyMUTEX_LOCK(gil->mutex) failed Python runtime state: unknown   Caught signal 6, backtrace follows: 0 libutils.dylib 0x0000000109b598e1 lsst::utils::(anonymous namespace)::signalHandler(int) + 81 1 libsystem_platform.dylib 0x00007fff205b0d7d (null) + 29 1 libsystem_platform.dylib 0x00007fff205b0d7d _sigtramp + 29 2 python 0x0000000108a9209b (null) + 35547 2 python 0x0000000108a9209b _PyEval_EvalFrameDefault + 35547 3 libsystem_c.dylib 0x00007fff204c0411 abort + 120 4 libpython3.8.dylib 0x000000010976eebc fatal_error + 60 5 libpython3.8.dylib 0x000000010976efe3 Py_FatalError + 19 6 libpython3.8.dylib 0x00000001096f571f take_gil + 671 7 libpython3.8.dylib 0x0000000109772b52 PyGILState_Ensure + 66 8 liblog.dylib 0x0000000108f9ffe6 lsst::log::detail::PyLogAppender::PyLogAppender() + 278 9 liblog.dylib 0x0000000108fa1a33 lsst::log::detail::PyLogAppender::ClazzPyLogAppender::newInstance() const + 35 10 liblog4cxx.11.0.0.dylib 0x000000010944e791 log4cxx::helpers::OptionConverter::instantiateByClassName(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, log4cxx::helpers::Class const&, log4cxx::helpers::ObjectPtrT<log4cxx::helpers::Object> const&) + 97 11 liblog4cxx.11.0.0.dylib 0x000000010944e578 log4cxx::helpers::OptionConverter::instantiateByKey(log4cxx::helpers::Properties&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, log4cxx::helpers::Class const&, log4cxx::helpers::ObjectPtrT<log4cxx::helpers::Object> const&) + 104 12 liblog4cxx.11.0.0.dylib 0x000000010945ba6d log4cxx::PropertyConfigurator::parseAppender(log4cxx::helpers::Properties&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) + 381 13 liblog4cxx.11.0.0.dylib 0x000000010945aae9 log4cxx::PropertyConfigurator::parseLogger(log4cxx::helpers::Properties&, log4cxx::helpers::ObjectPtrT<log4cxx::Logger>&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) + 2985 14 liblog4cxx.11.0.0.dylib 0x0000000109458e5d log4cxx::PropertyConfigurator::configureRootLogger(log4cxx::helpers::Properties&, log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggerRepository>&) + 221 15 liblog4cxx.11.0.0.dylib 0x0000000109458701 log4cxx::PropertyConfigurator::doConfigure(log4cxx::helpers::Properties&, log4cxx::helpers::ObjectPtrT<log4cxx::spi::LoggerRepository>&) + 785 16 liblog4cxx.11.0.0.dylib 0x0000000109458c57 log4cxx::PropertyConfigurator::configure(log4cxx::helpers::Properties&) + 55 17 liblog.dylib 0x0000000108f9dead lsst::log::Log::configure_prop(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) + 541 18 log.so 0x0000000108f71c18 void pybind11::cpp_function::initialize<void (*&)(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&), void, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, pybind11::name, pybind11::scope, pybind11::sibling>(void (*&)(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&), void (*)(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&), pybind11::name const&, pybind11::scope const&, pybind11::sibling const&)::'lambda'(pybind11::detail::function_call&)::operator()(pybind11::detail::function_call&) const + 88 19 log.so 0x0000000108f61d5d pybind11::cpp_function::dispatcher(_object*, _object*, _object*) + 4253

Kian-Tat Lim added a comment - 09/Jul/21 9:58 PM Sorry, no public macOS machines.

Tim Jenness added a comment - 09/Jul/21 10:11 PM Let me know if I can proxy some testing for you. Happy to screen share over Zoom.

Andy Salnikov added a comment - 11/Jul/21 4:48 AM OK, I figured out what the problem was - apparently dynamic loading works somewhat differently on Linux and MacOS which results in two copies of libpython being loaded on MacOS, while Linux somehow avoids this. I have added new PyLogAppender class to liblog. {so,dylib} shared library, my reasoning was that it may be used by other libraries without importing lsst.log Python module (which is not really true because PyLogAppender requires lsst.log , but we could make it optional). This adds dependency on libpython to liblog which was not there before. `lsst.log` is built as log.so and it depends on both liblog and libpython. On both platforms python executable is linked statically, and when python loads extension modules their Python API symbols are resolved against python binary, not libpython. That works for log.so, but when liblog is loaded on MacOS as log.so dependency it also forces loading of libpython to resolve its symbols. I did not play with RTLD flags to figure out if this is related to RTLD_LOCAL flag that python normally uses, my suspicion is that it is, if that is true then situation may be resolved by using RTLD_GLOBAL when loading log.so . What I did instead is moving PyLogAppender class to log.so , meaning that to use new appender we now have to import lsst.log first, it is not enough to link with liblog. Because we do it anyways I don't see an issue right now, if we want to get rid of this dependency later we can try to separate them. Jenkins is happy now, I think things are looking good and we can merge (and I made couple of small commits since my fix which don't change much).

Andy Salnikov added a comment - 12/Jul/21 4:07 PM Thanks for review and all suggestions. Finally merged, I hope nothing will be broken. There may be alternatives for how we split this stuff into shared/dynamic libraries, we'll figure it out as we go.