Infinite lock wait issue when emitting signal and datatype is not registered.

arunr

We're running into what seems to be a infinite wait for a lock when emitting a signal. I'm posting the callstack below:

#1  QBasicMutex::lockInternal() () from /lib64/libQt5Core.so.5
#2  QMutex::lock() () from /lib64/libQt5Core.so.5
#3  QMetaObject::activate(QObject*, int, int, void**) () from /lib64/libQt5Core.so.5
#4  rtmd::LoggerImpl::logEvent (this=this@entry=0x3703ce0, _t1=_t1@entry=rtmd::LogWarning, _t2=..., _t3=..., _t4=...) at /home/ramasaa/Sources/rvc/out-release/Common/private/moc_LoggerImpl.cpp:143
#5  rtmd::LoggerImpl::emitLogInternal (this=0x3703ce0, level=level@entry=rtmd::LogWarning, msgId=..., msg=...) at /home/ramasaa/Sources/rvc/local/Common/private/LoggerImpl.cxx:92
#6  rtmd::LoggerImpl::emitLog (this=<optimized out>, level=level@entry=rtmd::LogWarning, msgId=..., msg=...) at /home/ramasaa/Sources/rvc/local/Common/private/LoggerImpl.cxx:83
#7  rtmd::Logger::log (level=rtmd::LogWarning, msg=...) at /home/ramasaa/Sources/rvc/local/Common/Logger.cxx:138
#8  qt_message_print(QtMsgType, QMessageLogContext const&, QString const&) () from /lib64/libQt5Core.so.5
#9  qt_message(QtMsgType, QMessageLogContext const&, char const*, __va_list_tag*) () from /lib64/libQt5Core.so.5
#10 QMessageLogger::warning(char const*, ...) const () from /lib64/libQt5Core.so.5
#11 queuedConnectionTypes(QList<QByteArray> const&) () from /lib64/libQt5Core.so.5
#12 QMetaObject::activate(QObject*, int, int, void**) () from /lib64/libQt5Core.so.5
#13 rtmd::TreeNode::modified (this=this@entry=0x37163a0, _t1=_t1@entry=0x3731860,_t2=std::bitset = {...}) at /home/ramasaa/Sources/rvc/out-release/Common/moc_TreeNode.cpp:462

We emit a queued signal on frame#12. Since one of the types in the signals is custom type that's not registered with Qt this results in a qWarning which is intercepted by our logger (frame # 7). Our logger emits yet another signal to the logging threads, but at this point this thread just wait infinitely.

This problem is seen in Qt 5.9.2.

Qt's activate function locks a mutex it obtains corresponding to the sender from a mutex pool:

QMutexLocker locker(signalSlotLock(sender));//(line # 3661 qobject.cpp)

It detects that one of the types is not registered

 argumentTypes = queuedConnectionTypes(m.parameterTypes()); //(lines #3574 qobject.cpp)

then issues the qWarning without releasing this lock

 qWarning("QObject::connect: Cannot queue arguments of type '%s'\n" //(line #102 qobject.cpp).

Our logger intercepts this warning and emits another signal which requires another lock on a mutex object, which can be the same mutex object that was locked before the qWarning was issued.

The problem can be hard to reproduce, as the two mutexes are obtained for two different pointers/senders, which should map to the same entry in the mutex pool.

This seems like a bug in Qt's code. I see that qobject's activate function meticulously tracks the lock/unlock state of the mutex except maybe here, when it issues the qWarning, which can call external/user-defined functions.

It's possible that our code is not abiding by some Qt rule (like signal/slots result in undefined behaviour when the type is not registered), which we're not aware. Can someone with better knowledge of this system comment on this behaviour.

I can provide more information if needed.

SGaist

Hi and welcome to devnet,

How is your logger implemented ?

arunr

The actual file logging happens in a separate thread which catches a signal called logEvent. The logEvent signal is emitted by a util class , called Logger, that anyone can call.
When we detect a qWarning we call a function on the logger. This is implemented with the qInstallMessageHandler API.
So something like this:

void qMessageAsLogHandler(QtMsgType type, const QMessageLogContext& context, const QString& msg)
{
	Q_UNUSED(context);
	switch (type) {
		case QtDebugMsg:
		case QtInfoMsg:
		case QtWarningMsg:
			Logger::log(LogWarning, msg);
			break;
....
	}
}

void Logger::log(type, msg)
{
        emit logEvent(type, msg);
}

void Logger::installQtMsgHandler()
{
	qInstallMessageHandler(qMessageAsLogHandler);

}

SGaist

I wouldn't call a signal directly from the message handler. I would queue it.

arunr

What do you mean by that, that the connect to the signals from the message handler should be queued connections? But this problem is independent of that, as the lock from the message handler 's activate call happens before it checks if there are any queued connections.

SGaist

You don't get the lock if you don't emit that signal correct ?

arunr

Yes. No lock if no signal is emitted. The lock happens inside the 'emit signal' call.

SGaist

Hence my suggestion of queuing that signal emit.

arunr

But doesn't the queuing happens inside the 'emit signal' code, based on whether the receiver's connection is 'QueuedConnection' or if the receiver's thread is different than the emitting thread.
Is there another way of 'queuing the signal'.

kshegunov

~~Update to 5.9.8 at least.~~ [Edit: no good]
From what I saw in the current source (dev) the lock's been moved down and the actual type checks are made lockless through atomics.

Well, 5.13.x locks the same mutex at the same place, in dev it's been switched to atomics. So @SGaist's advice applies - use a workaround - queue the signal of your intercepting handler instead of emitting it directly.

@arunr said in Infinite lock wait issue when emitting signal and datatype is not registered.:

Is there another way of 'queuing the signal'.

QMetaObject::invokeMethod with Qt::QueuedConnection.

arunr

OK. Thanks. Will do.