Race with SwEditWinUIObject::get_state during UITest_writer_tests3?

[Stephan Bergmann]

With my (rather slow) local Linux ASan+UBSan build, I can occasionally see

> $ make UITest_writer_tests3 UITEST_TEST_NAME=hyperlinkdialog.HyperlinkDialog.test_insert_hyperlink

fail with soffice.bin hitting the assert in rtl_uString_newFromSubString 
at sal/rtl/strtmpl.cxx:1390

>     if ( count < 0 || beginIndex < 0 || beginIndex + count > pFrom->length )
>     {
>         assert(false); // fail fast at least in debug builds
>         IMPL_RTL_STRINGNAME( newFromLiteral )( ppThis, "!!br0ken!!", 10, 0 );
>         return;
>     }

with beginIndex=0 and count=4 but pFrom being the empty string.  This is 
on a remote worker thread #6

> #0  0x00007f5cb7bdc1ea in rtl_uString_newFromSubString(rtl_uString**, rtl_uString const*, sal_Int32, sal_Int32) (ppThis=0x7f5c251da460, pFrom=0x7f5cb79fde60 <aImplEmpty_rtl_uString>, beginIndex=0, count=4) at sal/rtl/strtmpl.cxx:1392
> #1  0x00007f5c1706f144 in rtl::OUString::copy(int, int) const (this=0x7f5c2547cb30, beginIndex=0, count=4) at include/rtl/ustring.hxx:2256
> #2  0x00007f5c1b8c6233 in SwTextNode::GetExpandText(SwRootFrame const*, int, int, bool, bool, bool, ExpandMode) const (this=0x614000108040, pLayout=0x614000103e40, nIdx=0, nLen=4, bWithNum=false, bAddSpaceAfterListLabelStr=false, bWithSpacesForLevel=false, eAdditionalMode=ExpandMode::ExpandFootnote) at sw/source/core/txtnode/ndtxt.cxx:3395
> #3  0x00007f5c1787230f in SwCursorShell::GetSelText() const (this=0x619000187480) at sw/source/core/crsr/crsrsh.cxx:2570
> #4  0x00007f5c198efbb8 in SwEditShell::GetSelectedText(rtl::OUString&, ParaBreakType) (this=0x619000187480, rBuf="", nHndlParaBrk=ParaBreakType::ToBlank) at sw/source/core/edit/edglss.cxx:268
> #5  0x00007f5c1ee55c81 in SwView::GetSelectionTextParam(bool, bool) (this=0x6170001ad000, bCompleteWrds=false, bEraseTrail=true) at sw/source/uibase/uiview/view.cxx:1598
> #6  0x00007f5c1ee554f6 in SwView::GetSelectionText(bool) (this=0x6170001ad000, bCompleteWrds=false) at sw/source/uibase/uiview/view.cxx:1589
> #7  0x00007f5c1ed10825 in SwEditWinUIObject::get_state() (this=0x604000a9a850) at sw/source/uibase/uitest/uiobject.cxx:43
> #8  0x00007f5c80f2e6cd in UIObjectUnoObj::getState() (this=0x611000336340) at vcl/source/uitest/uno/uiobject_uno.cxx:147
> #9  0x00007f5c80f2ee2d in non-virtual thunk to UIObjectUnoObj::getState() () at include/c++/11.0.0/bits/stl_tree.h:2246
> #10 0x00007f5c4c94e736 in gcc3::callVirtualMethod(void*, unsigned int, void*, _typelib_TypeDescriptionReference*, bool, unsigned long*, unsigned int, unsigned long*, double*) (pThis=0x611000336390, nVtableIndex=5, pRegisterReturn=0x7f5c267ef160, pReturnTypeRef=0x6080000c2aa0, bSimpleReturn=false, pStack=0x7f5c267ef1c0, nStack=0, pGPR=0x7f5c25508c60, pFPR=0x7f5c25508cc0) at bridges/source/cpp_uno/gcc3_linux_x86-64/callvirtualmethod.cxx:77
> #11 0x00007f5c4c948918 in cpp_call(bridges::cpp_uno::shared::UnoInterfaceProxy*, bridges::cpp_uno::shared::VtableSlot, _typelib_TypeDescriptionReference*, int, _typelib_MethodParameter*, void*, void**, _uno_Any**) (pThis=0x606000ace7a0, aVtableSlot=..., pReturnTypeRef=0x6080000c2aa0, nParams=0, pParams=0x0, pUnoReturn=0x60200052e6f0, pUnoArgs=0x0, ppUnoExc=0x7f5c25769880) at bridges/source/cpp_uno/gcc3_linux_x86-64/uno2cpp.cxx:233
> #12 0x00007f5c4c94533b in bridges::cpp_uno::shared::unoInterfaceProxyDispatch(uno_Interface*, typelib_TypeDescription const*, void*, void**, uno_Any**) (pUnoI=0x606000ace7a0, pMemberDescr=0x60f0000ae730, pReturn=0x60200052e6f0, pArgs=0x0, ppException=0x7f5c25769880) at bridges/source/cpp_uno/gcc3_linux_x86-64/uno2cpp.cxx:413
> #13 0x00007f5c4784866d in binaryurp::IncomingRequest::execute_throw(binaryurp::BinaryAny*, std::__debug::vector<binaryurp::BinaryAny, std::allocator<binaryurp::BinaryAny> >*) const (this=0x60d000317e60, returnValue=0x7f5c25768020, outArguments=0x7f5c25768060) at binaryurp/source/incomingrequest.cxx:235
> #14 0x00007f5c4784220b in binaryurp::IncomingRequest::execute() const (this=0x60d000317e60) at binaryurp/source/incomingrequest.cxx:78
> #15 0x00007f5c4792f799 in request(void*) (pThreadSpecificData=0x60d000317e60) at binaryurp/source/reader.cxx:85
> #16 0x00007f5cb0093cba in cppu_threadpool::JobQueue::enter(void const*, bool) (this=0x612000cadd40, nDisposeId=0x60600087c260, bReturnWhenNoJob=true) at cppu/source/threadpool/jobqueue.cxx:100
> #17 0x00007f5cb00bfdbe in cppu_threadpool::ORequestThread::run() (this=0x60600087c260) at cppu/source/threadpool/thread.cxx:165
> #18 0x00007f5cb00d42b3 in threadFunc(void*) (param=0x60600087c270) at include/osl/thread.hxx:185
> #19 0x00007f5cb7d35334 in osl_thread_start_Impl(void*) (pData=0x60c000362c80) at sal/osl/unx/thread.cxx:258
> #20 0x00007f5cb6255432 in start_thread (arg=<optimized out>) at /usr/src/debug/glibc-2.31-17-gab029a2801/nptl/pthread_create.c:477
> #21 0x00007f5cb61549d3 in clone () at /usr/src/debug/glibc-2.31-17-gab029a2801/sysdeps/unix/sysv/linux/x86_64/clone.S:95

while the main thread is idle at

> #0  futex_wait_cancelable (private=0, expected=0, futex_word=0x60e000025208) at /usr/src/debug/glibc-2.31-17-gab029a2801/sysdeps/nptl/futex-internal.h:183
> #1  __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x60e0000251b8, cond=0x60e0000251e0) at /usr/src/debug/glibc-2.31-17-gab029a2801/nptl/pthread_cond_wait.c:508
> #2  __pthread_cond_wait (cond=0x60e0000251e0, mutex=0x60e0000251b8) at /usr/src/debug/glibc-2.31-17-gab029a2801/nptl/pthread_cond_wait.c:638
> #3  0x00007f5cb64ab090 in __gthread_cond_wait (__mutex=<optimized out>, __cond=<optimized out>) at /home/sbergman/gcc/trunk/build/x86_64-pc-linux-gnu/libstdc++-v3/include/x86_64-pc-linux-gnu/bits/gthr-default.h:865
> #4  std::condition_variable::wait(std::unique_lock<std::mutex>&) (this=<optimized out>, __lock=...) at /home/sbergman/gcc/trunk/src/libstdc++-v3/src/c++11/condition_variable.cc:53
> #5  0x00007f5c8131294d in std::condition_variable::wait<SvpSalYieldMutex::doAcquire(unsigned int)::$_0>(std::unique_lock<std::mutex>&, SvpSalYieldMutex::doAcquire(unsigned int)::$_0) (this=0x60e0000251e0, __lock=..., __p=...) at include/c++/11.0.0/condition_variable:111
> #6  0x00007f5c8131189a in SvpSalYieldMutex::doAcquire(unsigned int) (this=0x60e000025180, nLockCount=1) at vcl/headless/svpinst.cxx:342
> #7  0x00007f5c7d1a239e in comphelper::SolarMutex::acquire(unsigned int) (this=0x60e000025180, nLockCount=1) at include/comphelper/solarmutex.hxx:86
> #8  0x00007f5c802a3a49 in SalInstance::AcquireYieldMutex(unsigned int) (this=0x611000001d00, nCount=1) at vcl/source/app/salvtables.cxx:118
> #9  0x00007f5c8131653a in SvpSalInstance::DoYield(bool, bool) (this=0x611000001d00, bWait=true, bHandleAllCurrentEvents=false) at vcl/headless/svpinst.cxx:503
> #10 0x00007f5c8071f8a4 in ImplYield(bool, bool) (i_bWait=true, i_bAllEvents=false) at vcl/source/app/svapp.cxx:455
> #11 0x00007f5c8071ea88 in Application::Yield() () at vcl/source/app/svapp.cxx:519
> #12 0x00007f5c8071e6c8 in Application::Execute() () at vcl/source/app/svapp.cxx:434
> #13 0x00007f5cb6e7022d in desktop::Desktop::Main() (this=0x7f5c4dbb6080) at desktop/source/app/app.cxx:1600
> #14 0x00007f5c807c8bcd in ImplSVMain() () at vcl/source/app/svmain.cxx:201
> #15 0x00007f5c807d2b91 in SVMain() () at vcl/source/app/svmain.cxx:233
> #16 0x00007f5cb705f29d in soffice_main() () at desktop/source/app/sofficemain.cxx:98
> #17 0x000000000032d38d in sal_main () at desktop/source/app/main.c:48
> #18 0x000000000032d367 in main (argc=7, argv=0x7ffe05dcfc48) at desktop/source/app/main.c:47
> #19 0x00007f5cb607a042 in __libc_start_main (main=0x32d340 <main>, argc=7, argv=0x7ffe05dcfc48, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffe05dcfc38) at /usr/src/debug/glibc-2.31-17-gab029a2801/csu/libc-start.c:308
> #20 0x0000000000250b3e in _start ()

(at least it is idle once I come around to generate the backtraces, 
which doesn't happen automatically upon SIGABRT for that ASan build; so 
I needed to hack the assert into an endless loop and attach gdb after it 
got hit).  The python.bin process is at

> Traceback (most recent call first):
>   File "uitest/uitest/uihelper/common.py", line 11, in get_state_as_dict
>     return convert_property_values_to_dict(ui_object.getState())
>   File "sw/qa/uitest/writer_tests3/hyperlinkdialog.py", line 79, in test_insert_hyperlink
>     self.assertEqual(get_state_as_dict(xedit)["SelectedText"], "link")
>   File "instdir/program/python-core-3.8.4/lib/unittest/case.py", line 633, in _callTestMethod
>     method()
>   File "instdir/program/python-core-3.8.4/lib/unittest/case.py", line 1700, in run
>   File "instdir/program/python-core-3.8.4/lib/unittest/case.py", line 736, in __call__
>     return self.run(*args, **kwds)
>   File "instdir/program/python-core-3.8.4/lib/unittest/suite.py", line 378, in run
>   File "instdir/program/python-core-3.8.4/lib/unittest/suite.py", line 84, in __call__
>     return self.run(*args, **kwds)
>   File "instdir/program/python-core-3.8.4/lib/unittest/runner.py", line 432, in run
>   File "uitest/test_main.py", line 128, in <module>
>     result = unittest.TextTestRunner(stream=sys.stdout, verbosity=2).run(test_suite)

I assume that there is a race, and some other thread was modifying the 
data in parallel with thread #6 accessing it.  (But any trace of that 
other thread's activity is gone by the time I get the soffice.bin 
backtraces; see above.)  I already verified that this is probably not a 
SolarMutex issue at least on thread #6's end, by sticking

   DBG_TESTSOLARMUTEX();

at the top of SwTextNode::GetExpandText, which never fired.

Any idea how to debug this further?