Results 1 to 5 of 5

Thread: QDebug assert failure crash in QRingBuffer

  1. #1
    Join Date
    Mar 2020
    Posts
    6
    Qt products
    Qt5
    Platforms
    Unix/X11 Windows

    Default QDebug assert failure crash in QRingBuffer

    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

    Qt Code:
    1. #ifndef SCOPEDEBUG_H
    2. #define SCOPEDEBUG_H
    3.  
    4.  
    5. #define SHELL_RESET "\033[0m"
    6.  
    7. #define SHELL_RED "\033[031m"
    8. #define SHELL_GREEN "\033[032m"
    9. #define SHELL_YELLOW "\033[033m"
    10. #define SHELL_BLUE "\033[034m"
    11.  
    12.  
    13. #include <QDebug>
    14. #include <QString>
    15. #include <QElapsedTimer>
    16.  
    17. //#define NO_DEBUG_CALL_TRACE
    18.  
    19. #ifndef NO_DEBUG_CALL_TRACE
    20.  
    21. class Scope
    22. {
    23. public:
    24. Scope(const char *fn, const char *s="", const char* e="");
    25. ~Scope();
    26.  
    27. const char *func, *start, *end;
    28. };
    29.  
    30.  
    31. class ScopeTimer : Scope
    32. {
    33. public:
    34. ScopeTimer(const char *fn, const char *s="", const char* e="");
    35. ~ScopeTimer();
    36.  
    37. QElapsedTimer timer;
    38. };
    39.  
    40.  
    41.  
    42. # define DEBUG_ENTRY_NAME(name) Scope DBG(name)
    43. # define DEBUG_ENTRY DEBUG_ENTRY_NAME(__PRETTY_FUNCTION__)
    44. # define DEBUG_COLOR_ENTRY(color) Scope DBG(__PRETTY_FUNCTION__, color, SHELL_RESET)
    45. # define DEBUG_IMPORTANT_ENTRY DEBUG_COLOR_ENTRY(SHELL_GREEN)
    46.  
    47. # define DEBUG_TIME_ENTRY ScopeTimer DBG(__PRETTY_FUNCTION__)
    48.  
    49. #else
    50. # define DEBUG_ENTRY_NAME(name)
    51. # define DEBUG_ENTRY
    52. # define DEBUG_COLOR_ENTRY(color)
    53. # define DEBUG_IMPORTANT_ENTRY
    54. # define DEBUG_TIME_ENTRY
    55. #endif // NO_DEBUG_CALLTRACE
    56.  
    57. #endif // SCOPEDEBUG_H
    To copy to clipboard, switch view to plain text mode 

    And this is the cpp file:

    Qt Code:
    1. #include "app/scopedebug.h"
    2.  
    3. #ifndef NO_DEBUG_CALL_TRACE
    4.  
    5. static uint thread_local stackLevel = 0;
    6.  
    7. Scope::Scope(const char *fn, const char *s, const char *e) :
    8. func(fn),
    9. start(s),
    10. end(e)
    11. {
    12. qDebug().nospace().noquote()
    13. << start << QByteArray(" ").repeated(stackLevel) << ">>> " << func << end;
    14. stackLevel++;
    15. }
    16.  
    17. Scope::~Scope()
    18. {
    19. stackLevel--;
    20. qDebug().nospace().noquote()
    21. << start << QByteArray(" ").repeated(stackLevel) << "<<< " << func << end;
    22. }
    23.  
    24. ScopeTimer::ScopeTimer(const char *fn, const char *s, const char *e) :Scope(fn, s, e)
    25. {
    26. timer.start();
    27. }
    28.  
    29. ScopeTimer::~ScopeTimer()
    30. {
    31. qDebug() << "TOOK" << timer.elapsed() << "ms";
    32. }
    33.  
    34. #endif
    To copy to clipboard, switch view to plain text mode 

    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:

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

    QRingBuffer::free has an assert and I get always 70 bytes < 45 -> assert failure.
    Last edited by gfgit; 14th March 2020 at 14:58.

  2. #2
    Join Date
    Jan 2008
    Location
    Alameda, CA, USA
    Posts
    4,481
    Thanks
    252
    Thanked 711 Times in 701 Posts
    Qt products
    Qt5
    Platforms
    Windows Android

    Default Re: QDebug assert failure crash in QRingBuffer

    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.
    <=== The Great Pumpkin says ===>
    Please use CODE tags when posting source code so it is more readable. Click "Go Advanced" and then the "#" icon to insert the tags. Paste your code between them.

  3. #3
    Join Date
    Mar 2020
    Posts
    6
    Qt products
    Qt5
    Platforms
    Unix/X11 Windows

    Default Re: QDebug assert failure crash in QRingBuffer

    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:
    Qt Code:
    1. bool JobPathEditor::clearJob()
    2. {
    3. DEBUG_ENTRY;
    4. ...
    5. }
    To copy to clipboard, switch view to plain text mode 
    So it's just a:
    Qt Code:
    1. Scope DBG(__PRETTY_FUNCTION__);
    To copy to clipboard, switch view to plain text mode 
    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:
    Qt Code:
    1. extern uint stackLevel;
    To copy to clipboard, switch view to plain text mode 
    And in scopedebug.cpp it was initializet:
    Qt Code:
    1. uint stackLevel = 0;
    To copy to clipboard, switch view to plain text mode 
    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:
    Qt Code:
    1. static uint thread_local stackLevel = 0;
    To copy to clipboard, switch view to plain text mode 
    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.
    Qt Code:
    1. Q_GLOBAL_STATIC(QFile, gLogFile);
    2. static QtMessageHandler defaultHandler;
    3.  
    4. void myMessageOutput(QtMsgType type, const QMessageLogContext &context, const QString &msg)
    5. {
    6. QString str;
    7. //const QString fmt = QStringLiteral("%1: %2 (%3:%4, %5)\n");
    8. static const QString fmt = QStringLiteral("%1: %2\n");
    9. switch (type) {
    10. case QtDebugMsg:
    11. str = fmt.arg(QStringLiteral("Debug")).arg(msg); //.arg(context.file).arg(context.line).arg(context.function);
    12. break;
    13. case QtInfoMsg:
    14. str = fmt.arg(QStringLiteral("Info")).arg(msg); //.arg(context.file).arg(context.line).arg(context.function);
    15. break;
    16. case QtWarningMsg:
    17. str = fmt.arg(QStringLiteral("Warning")).arg(msg); //.arg(context.file).arg(context.line).arg(context.function);
    18. break;
    19. case QtCriticalMsg:
    20. str = fmt.arg(QStringLiteral("Critical")).arg(msg); //.arg(context.file).arg(context.line).arg(context.function);
    21. break;
    22. case QtFatalMsg:
    23. str = fmt.arg(QStringLiteral("Fatal")).arg(msg); //.arg(context.file).arg(context.line).arg(context.function);
    24. }
    25.  
    26. QTextStream s(gLogFile());
    27. s << str;
    28.  
    29. defaultHandler(type, context, msg);
    30. }
    31.  
    32. //Called in main() right after QApplication constructor
    33. void setupLogger()
    34. {
    35. const QString path = qApp->applicationDirPath();
    36. QFile *logFile = gLogFile();
    37. logFile->setFileName(path + QStringLiteral("/logs/fremolog.log"));
    38. logFile->open(QFile::WriteOnly | QFile::Append | QFile::Text);
    39. if(!logFile->isOpen())
    40. {
    41. QDir dir(path);
    42. dir.mkdir("logs");
    43. logFile->open(QFile::WriteOnly | QFile::Append | QFile::Text);
    44. }
    45. if(logFile->isOpen())
    46. {
    47. defaultHandler = qInstallMessageHandler(myMessageOutput);
    48. }
    49. else {
    50. qDebug() << "Cannot open Log file:" << logFile->fileName() << "Error:" << logFile->errorString();
    51. }
    52. }
    To copy to clipboard, switch view to plain text mode 
    Then when QTextStrem is destoyed (myMessageOutput returns) it calls flush() of QFileDevice
    Qt Code:
    1. bool QFileDevice::flush()
    2. {
    3. Q_D(QFileDevice);
    4. if (!d->fileEngine) {
    5. qWarning("QFileDevice::flush: No file engine. Is IODevice open?");
    6. return false;
    7. }
    8.  
    9. if (!d->writeBuffer.isEmpty()) {
    10. qint64 size = d->writeBuffer.nextDataBlockSize();
    11. qint64 written = d->fileEngine->write(d->writeBuffer.readPointer(), size);
    12. if (written > 0)
    13. d->writeBuffer.free(written); //CRASH here
    14. //size is <optimized out> and written is always 78 when the program crashes.
    To copy to clipboard, switch view to plain text mode 
    Then in QIODvicePrivate::RingBufferRef::free()
    Qt Code:
    1. inline void free(qint64 bytes) { Q_ASSERT(m_buf); m_buf->free(bytes); }
    2. //m_buf is valid:
    3. //basicBlockSize = 16384
    4. //bufferSize = 0
    5. //buffers has 1 item
    6. //this QRingChunk items has:
    7. //headOffset = 0
    8. //tailOffset = 0
    9. //QByteArray chunk = "Debug: Starting WORKER: rs check\r\nDebug: >>> bool JobPathEditor::clearJob()\nW_32bit2-Debug/test_new_edit_system.db\"\r\n?"
    10. //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
    To copy to clipboard, switch view to plain text mode 
    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:
    Qt Code:
    1. void QRingBuffer::free(qint64 bytes)
    2. {
    3. Q_ASSERT(bytes <= bufferSize); //Fails with bytes = 78 and bufferSize = 0
    4. ...
    To copy to clipboard, switch view to plain text mode 
    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?

  4. #4
    Join Date
    Jan 2008
    Location
    Alameda, CA, USA
    Posts
    4,481
    Thanks
    252
    Thanked 711 Times in 701 Posts
    Qt products
    Qt5
    Platforms
    Windows Android

    Default Re: QDebug assert failure crash in QRingBuffer

    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.
    <=== The Great Pumpkin says ===>
    Please use CODE tags when posting source code so it is more readable. Click "Go Advanced" and then the "#" icon to insert the tags. Paste your code between them.

  5. #5
    Join Date
    Mar 2020
    Posts
    6
    Qt products
    Qt5
    Platforms
    Unix/X11 Windows

    Default Re: QDebug assert failure crash in QRingBuffer

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

Similar Threads

  1. Replies: 3
    Last Post: 27th July 2011, 09:30
  2. Assert failure with tablet installed
    By Spectralist in forum Qt Programming
    Replies: 2
    Last Post: 21st April 2011, 13:31
  3. Problem debugging Assert failure.
    By Doug Broadwell in forum Qt Programming
    Replies: 3
    Last Post: 3rd January 2009, 18:39
  4. Debugging ASSERT failure in Qt header.
    By Doug Broadwell in forum Qt Programming
    Replies: 6
    Last Post: 27th December 2008, 01:40
  5. QWT assert failure
    By Andimat in forum Qwt
    Replies: 1
    Last Post: 21st June 2007, 14:36

Bookmarks

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •  
Digia, Qt and their respective logos are trademarks of Digia Plc in Finland and/or other countries worldwide.