pyqgis - Plugin crashes QGIS 2.18 if running simuntaneously with python console

I'm currently developing plugin for QGIS 2.18. From the begining I'm having the same issue. QGIS 2.18 crashes if I run python console while plugin is working something.

I saw that print statements could be the cause, so I redirected them to the log file. It's interesting because plugin works perfectly while python console is not working and I really don't have a clue.

This is what I get after crash:

Fatal: Assertion [useCount == 0] failed at ../src/PositionCache.cpp 263


Stacktrace (piped through c++filt):

/usr/bin/qgis.bin(+0xaffa)[0x555dc646affa]
/usr/bin/qgis.bin(+0xb235)[0x555dc646b235]
/usr/lib/x86_64-linux-gnu/libQtCore.so.4(qt_message_output(QtMsgType, char const*)+0x2f)[0x7f64cdc90e9f]
/usr/lib/x86_64-linux-gnu/libQtCore.so.4(+0x70371)[0x7f64cdc91371]
/usr/lib/x86_64-linux-gnu/libQtCore.so.4(qFatal(char const*, ...)+0xa1)[0x7f64cdc91c91]
/usr/lib/libqscintilla2.so.12(Platform::Assert(char const*, char const*, int)+0x32)[0x7f64c83a632c]
/usr/lib/libqscintilla2.so.12(LineLayoutCache::AllocateForLevel(int, int)+0x35)[0x7f64c84cbafb]
/usr/lib/libqscintilla2.so.12(LineLayoutCache::Retrieve(int, int, int, int, int, int)+0x34)[0x7f64c84cbe46]

/usr/lib/libqscintilla2.so.12(EditView::RetrieveLineLayout(int, EditModel const&)+0x143)[0x7f64c84b286d]
/usr/lib/libqscintilla2.so.12(Editor::SetAnnotationHeights(int, int)+0xd1)[0x7f64c84a2605]
/usr/lib/libqscintilla2.so.12(Editor::CheckModificationForWrap(DocModification)+0xc4)[0x7f64c849622c]
/usr/lib/libqscintilla2.so.12(Editor::NotifyModified(Document*, DocModification, void*)+0x790)[0x7f64c8496a1e]
/usr/lib/libqscintilla2.so.12(Document::NotifyModified(DocModification)+0xf5)[0x7f64c8486391]
/usr/lib/libqscintilla2.so.12(Document::InsertString(int, char const*, int)+0x309)[0x7f64c8481d9f]
/usr/lib/libqscintilla2.so.12(Editor::WndProc(unsigned int, unsigned long, long)+0x17a1)[0x7f64c84a6111]
/usr/lib/libqscintilla2.so.12(ScintillaBase::WndProc(unsigned int, unsigned long, long)+0xf16)[0x7f64c84d8a90]
/usr/lib/libqscintilla2.so.12(QsciScintillaQt::WndProc(unsigned int, unsigned long, long)+0x53)[0x7f64c83a79a1]
/usr/lib/libqscintilla2.so.12(QsciScintillaBase::SendScintilla(unsigned int, unsigned long, char const*) const+0x3e)[0x7f64c836d5fe]

/usr/lib/libqscintilla2.so.12(QsciScintilla::append(QString const&)+0x78)[0x7f64c836543c]
/usr/lib/python2.7/dist-packages/PyQt4/Qsci.x86_64-linux-gnu.so(+0xdc209)[0x7f641ca5e209]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x8a51)[0x7f64203d6751]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x85c)[0x7f64204ff01c]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(+0x13e2e0)[0x7f64204552e0]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyObject_Call+0x43)[0x7f64204281e3]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(+0x18531c)[0x7f642049c31c]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyObject_Call+0x43)[0x7f64204281e3]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyEval_CallObjectWithKeywords+0x47)[0x7f64204fe447]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyFile_WriteObject+0x152)[0x7f642046b4d2]

/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x582c)[0x7f64203d352c]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x7124)[0x7f64203d4e24]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x85c)[0x7f64204ff01c]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(+0x13e2e0)[0x7f64204552e0]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyObject_Call+0x43)[0x7f64204281e3]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(+0x18531c)[0x7f642049c31c]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyObject_Call+0x43)[0x7f64204281e3]
/usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0(PyEval_CallObjectWithKeywords+0x47)[0x7f64204fe447]
/usr/lib/python2.7/dist-packages/sip.x86_64-linux-gnu.so(+0xfe44)[0x7f6420004e44]
/usr/lib/python2.7/dist-packages/PyQt4/QtCore.so(+0x8be60)[0x7f641fbe2e60]

/usr/lib/python2.7/dist-packages/PyQt4/QtCore.so(+0xdc59e)[0x7f641fc3359e]
/usr/lib/x86_64-linux-gnu/libQtCore.so.4(+0x7ae3c)[0x7f64cdc9be3c]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f64c5e5e6ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f64cc6d23dd]

The behavior is the same on Windows

Answer

This is indeed an effect of using the print statement and having the python console open. And using the logging module as proposed is a very good approach to solving this issue.

Here follow some insights into what exactly happens. It boils down to print() internally calling QCoreApplication::processEvents() and processEvents() is evil and dangerous.

The python console will always call QCoreAppliation::processEvents() when something is printed. The reason for this is, that the console's painting events need to be processed in order to make the printed text appear on the console.

Events are processed whenever QGIS has time normally. But in the python console sometimes long-running loops are performed which keep QGIS busy, so it will not work on pending events until the loop is finished.

However, processEvents() will not only work on display updates but also handle user input and signal/slot connections. This will sometimes execute code recursively which was not designed to be run recursively or otherwise execute code in a different context than expected .

1. Use a module like logging or QgsMessageLog instead of using print for debugging


2. Especially do not use print() in slots connected to slots connected to signals triggered by user input (like map canvas navigation events)


3. Do not use processEvents() calls in your own code. If you are using QGIS 3, consider implementing a QgsTask for longruning code.

Situation in QGIS 3

In QGIS 3 print() no longer triggers a processEvents() call and therefore is safe to use. However, calling processEvents() from your own code is still dangerous.