QDebug assert failure crash in QRingBuffer

[gfgit]

Hi,
I'm using a simple class called Scope that prints the current function name in cosructor and destructor for debugging purposes.
So I get a message when the programs executes a function and when it leaves.

This is the header


#ifndef SCOPEDEBUG_H
#define SCOPEDEBUG_H


#define SHELL_RESET "\033[0m"

#define SHELL_RED "\033[031m"
#define SHELL_GREEN "\033[032m"
#define SHELL_YELLOW "\033[033m"
#define SHELL_BLUE "\033[034m"


#include <QDebug>
#include <QString>
#include <QElapsedTimer>

//#define NO_DEBUG_CALL_TRACE

#ifndef NO_DEBUG_CALL_TRACE

class Scope
{
public:
Scope(const char *fn, const char *s="", const char* e="");
~Scope();

const char *func, *start, *end;
};


class ScopeTimer : Scope
{
public:
ScopeTimer(const char *fn, const char *s="", const char* e="");
~ScopeTimer();

QElapsedTimer timer;
};



# define DEBUG_ENTRY_NAME(name) Scope DBG(name)
# define DEBUG_ENTRY DEBUG_ENTRY_NAME(__PRETTY_FUNCTION__)
# define DEBUG_COLOR_ENTRY(color) Scope DBG(__PRETTY_FUNCTION__, color, SHELL_RESET)
# define DEBUG_IMPORTANT_ENTRY DEBUG_COLOR_ENTRY(SHELL_GREEN)

# define DEBUG_TIME_ENTRY ScopeTimer DBG(__PRETTY_FUNCTION__)

#else
# define DEBUG_ENTRY_NAME(name)
# define DEBUG_ENTRY
# define DEBUG_COLOR_ENTRY(color)
# define DEBUG_IMPORTANT_ENTRY
# define DEBUG_TIME_ENTRY
#endif // NO_DEBUG_CALLTRACE

#endif // SCOPEDEBUG_H

And this is the cpp file:


#include "app/scopedebug.h"

#ifndef NO_DEBUG_CALL_TRACE

static uint thread_local stackLevel = 0;

Scope::Scope(const char *fn, const char *s, const char *e) :
func(fn),
start(s),
end(e)
{
qDebug().nospace().noquote()
<< start << QByteArray(" ").repeated(stackLevel) << ">>> " << func << end;
stackLevel++;
}

Scope::~Scope()
{
stackLevel--;
qDebug().nospace().noquote()
<< start << QByteArray(" ").repeated(stackLevel) << "<<< " << func << end;
}

ScopeTimer::ScopeTimer(const char *fn, const char *s, const char *e) :Scope(fn, s, e)
{
timer.start();
}

ScopeTimer::~ScopeTimer()
{
qDebug() << "TOOK" << timer.elapsed() << "ms";
}

#endif

The crash happens doesn't always happen and also it only happens if I start my program with debugger.
Also if it's relevant I also start a QRunnable in the global threadpool and it also calls qDebug() at about the same time I think but the documentation says that qDebug() is thread-safe.
Qt Version: 5.11.3 kit
Compiler: MinGW 32 bit
OS: Windows 8.1 64 bit

This is the trace:


1 QMessageLogger::fatal qlogging.cpp 872 0x6b98fc96
2 qt_assert qglobal.cpp 3202 0x6b98a961
3 QRingBuffer::free qringbuffer.cpp 113 0x6b9e7295
4 QIODevicePrivate::QRingBufferRef::free qiodevice_p.h 100 0x6ba594f0
5 QFileDevice::flush qfiledevice.cpp 294 0x6ba594f0
6 QTextStreamPrivate::flushWriteBuffer qtextstream.cpp 609 0x6bb63e89
7 QTextStream::~QTextStream qtextstream.cpp 1163 0x6bb63f57
8 myMessageOutput main.cpp 48 0x406bbc
9 qt_message_print qlogging.cpp 1791 0x6b98f5dd
10 qt_message_output qlogging.cpp 1849 0x6b99041d
11 QDebug::~QDebug qdebug.cpp 156 0x6ba4d2bf
12 Scope::Scope scopedebug.cpp 12 0x40cf5a
13 JobPathEditor::clearJob jobpatheditor.cpp 293 0x41240f

QRingBuffer::free has an assert and I get always 70 bytes < 45 -> assert failure.

[d_stranz]

You create and start a new QElapsedTimer instance with each ScopeTimer instance. If internally this means having to acquire a Windows resource handle, you could be running out of handles if your recursion is going deep enough. I do not know if this is the case, but if the code you have posted accurately reflects the extent of your program (that is, there isn't something else you are doing that could corrupt memory), there isn't much wrong with it aside from the private inheritance from Scope by ScopeTimer (which might be intentional, I don't know).

So instead of creating a new timer for every instance, use a single static QElapsedTimer for all ScopeTimer instances. In the ScopeTimer constructor, check if the timer isValid(), and if not, start() it. Record the current elapsed() value in a member variable. In the destructor, call elapsed() again, and calculate the difference between that and the saved value.

[gfgit]

Hi,
Thank you for your help!
Private inheritance of Scope was a mistake.
But ScopeTimer was really just an experiment, it's not used anywhere in the code.
clearJob() has a DEBUG_ENTRY macro:


bool JobPathEditor::clearJob()
{
DEBUG_ENTRY;
...
}
So it's just a:

Scope DBG(__PRETTY_FUNCTION__);
On the stack and the constructor calls qDebug(). No timers involved.

My guess is that the problem might be stackLevel variable, but I don't know how.
Previously it was declared in scopedebug.h as following:

extern uint stackLevel;
And in scopedebug.cpp it was initializet:

uint stackLevel = 0;
Since I started using QThreadPool I tried to change stackLevel to be thread_local although I'm using it only in the main thread. So now it's defined only in the cpp file:

static uint thread_local stackLevel = 0;
The program crashes the same!

The program is quite big so I cannot post the whole source and small QThreadPool experiments are not crashing.

I forgot to add that I override the message handler to generate a log file.

Q_GLOBAL_STATIC(QFile, gLogFile);
static QtMessageHandler defaultHandler;

void myMessageOutput(QtMsgType type, const QMessageLogContext &context, const QString &msg)
{
QString str;
//const QString fmt = QStringLiteral("%1: %2 (%3:%4, %5)\n");
static const QString fmt = QStringLiteral("%1: %2\n");
switch (type) {
case QtDebugMsg:
str = fmt.arg(QStringLiteral("Debug")).arg(msg); //.arg(context.file).arg(context.line).arg(context.f unction);
break;
case QtInfoMsg:
str = fmt.arg(QStringLiteral("Info")).arg(msg); //.arg(context.file).arg(context.line).arg(context.f unction);
break;
case QtWarningMsg:
str = fmt.arg(QStringLiteral("Warning")).arg(msg); //.arg(context.file).arg(context.line).arg(context.f unction);
break;
case QtCriticalMsg:
str = fmt.arg(QStringLiteral("Critical")).arg(msg); //.arg(context.file).arg(context.line).arg(context.f unction);
break;
case QtFatalMsg:
str = fmt.arg(QStringLiteral("Fatal")).arg(msg); //.arg(context.file).arg(context.line).arg(context.f unction);
}

QTextStream s(gLogFile());
s << str;

defaultHandler(type, context, msg);
}

//Called in main() right after QApplication constructor
void setupLogger()
{
const QString path = qApp->applicationDirPath();
QFile *logFile = gLogFile();
logFile->setFileName(path + QStringLiteral("/logs/fremolog.log"));
logFile->open(QFile::WriteOnly | QFile::Append | QFile::Text);
if(!logFile->isOpen())
{
QDir dir(path);
dir.mkdir("logs");
logFile->open(QFile::WriteOnly | QFile::Append | QFile::Text);
}
if(logFile->isOpen())
{
defaultHandler = qInstallMessageHandler(myMessageOutput);
}
else {
qDebug() << "Cannot open Log file:" << logFile->fileName() << "Error:" << logFile->errorString();
}
}
Then when QTextStrem is destoyed (myMessageOutput returns) it calls flush() of QFileDevice

bool QFileDevice::flush()
{
Q_D(QFileDevice);
if (!d->fileEngine) {
qWarning("QFileDevice::flush: No file engine. Is IODevice open?");
return false;
}

if (!d->writeBuffer.isEmpty()) {
qint64 size = d->writeBuffer.nextDataBlockSize();
qint64 written = d->fileEngine->write(d->writeBuffer.readPointer(), size);
if (written > 0)
d->writeBuffer.free(written); //CRASH here
//size is <optimized out> and written is always 78 when the program crashes.
Then in QIODvicePrivate::RingBufferRef::free()

inline void free(qint64 bytes) { Q_ASSERT(m_buf); m_buf->free(bytes); }
//m_buf is valid:
//basicBlockSize = 16384
//bufferSize = 0
//buffers has 1 item
//this QRingChunk items has:
//headOffset = 0
//tailOffset = 0
//QByteArray chunk = "Debug: Starting WORKER: rs check\r\nDebug: >>> bool JobPathEditor::clearJob()\nW_32bit2-Debug/test_new_edit_system.db\"\r\n?"
//NOTE: I escaped the characters as Qt Creator shows them. The QByteArray is long 16384 bytes and after the last \r\n thera are a lot of ? characters
So here two messages are concatenated: "Starting WORKER: rs check" from the QRunnable::run() in a thread and " >>> bool JobPathEditor::clearJob()" from the min thread in Scope constructor.
I don't now the origin of "W_32bit2-Debug/test_new_edit_system.db" it is never printed neither in Qt Creator console neither in the log file.
It's the last portion of the path of the file opened by the program but I don't know how it ended there.
The file path is printed when loading the file but it's in a completely different part of the code and happens way before. In the middle qDebug() is used multiple times.
The full message is: Loading: "C:/Filippo/Qt_project/build-fremo_db_5-Desktop_Qt_5_11_3_MinGW_32bit2-Debug/test_new_edit_system.db"
Finally:

void QRingBuffer::free(qint64 bytes)
{
Q_ASSERT(bytes <= bufferSize); //Fails with bytes = 78 and bufferSize = 0
...
The assert failure always happens in the main thread and myMessageOutput is called from the main thread but only with the second message: " >>> bool JobPathEditor::clearJob()"
Maybe the problem is the globally shared QFile not thread safe?
If so how should I change the code?

[d_stranz]

Maybe the problem is the globally shared QFile not thread safe?

That's a possibility. You should try protecting writes to the file with a QMutex or some other access protection mechanism. Be sure to match lock() and unlock() calls.

[gfgit]

I protected the QTextStream and QFile with a global QMutex and it solved the issue.
Thank you very much!!!