Unsolved Class and thread to manage debug output
-
@SPlatten I just implemented simple debug cout message code block and have noticed same issues I was having using plain C/C++. The multi line cout code would miss lines at random.
I had an excessive discussion about the issue in another forum and the conclusion was - it is an OS issue and cannot be easily resolved.
Typically this problem showed up when I used both cout and cerr messages - they would not be put to "console" in expected code sequence.
-
@AnneRanch thank you, what operating system are you using?
I am developing on an iMAC running:
macOS Catalina Version 10.15.6
-
@AnneRanch said in Class and thread to manage debug output:
Typically this problem showed up when I used both cout and cerr messages - they would not be put to "console" in expected code sequence.
Assuming you are C++11 or later, I am surprised. As per https://en.cppreference.com/w/cpp/io/cerr
- Anything sent to
cerr
should be flushed immediately. - Anything sent to
cerr
should first flushcout
.
So i'd have expected them to appear in the order emitted from code, though one could always put in flushes explicitly to make sure.
@SPlatten
I presume the "missing characters" problem here is purely to do with the Qt Creator console handling having some limit? If you sent these outputs to file I would expect nothing to be missing? If that is so, it may not be nice but could you cut up long output and send it in chunks if it's a character-count limitation? - Anything sent to
-
@JonB Thats exactly what I do in a helper thread, however despite cutting it into chunks and outputting chunks in a thread it still doesn't output everything.
-
This is the new version of the class using a Wait Conditiion and Mutex, it isn't right, can someone help me fix it?
Prototype:
/** * File: clsDebugService.h * Notes: This file contains the prototype for the clsDebugService class. ******************************************************************************* * Class: clsDebugService * * Static Members: * msMutex Mutex * msStack Stack of messages to service * msulngDbgSeqNo Debugging sequence number * * Static Methods: * pushDebug Appends a debug message string to the log * serviceDebugQueue Installs a thread to service the debug stack * spMutex Access method to get address of mutex * * Members: * mblnTerminate true to terminate thread * * Methods: * clsDebugService Class constructor * ~clsDebugService Class destructor * run Thread body ******************************************************************************* * History: 2020/07/16 Created by Simon Platten */ #ifndef CLSDEBUGSERVICE_H #define CLSDEBUGSERVICE_H #include <QStack> #include <QThread> #include <QWaitCondition> class clsDebugService : public QThread { private: static ulong msulngDbgSeqNo; static clsDebugService* mspService; static QStack<QString> msStack; static QMutex msMutex; bool mblnTerminate; QWaitCondition mWaitCondition; void run(); public: explicit clsDebugService(); ~clsDebugService(); static void pushDebug(QString strMsg); static void serviceDebugQueue(); static QMutex* spMutex() { return &msMutex; } }; #endif // CLSDEBUGSERVICE_H
Implementation:
#include <iostream> #include <clsDebugService.h> #include <clsMainWnd.h> //Static members QMutex clsDebugService::msMutex; QStack<QString> clsDebugService::msStack; ulong clsDebugService::msulngDbgSeqNo = 0; clsDebugService* clsDebugService::mspService = nullptr; /** * @brief clsDebugService::clsDebugService */ clsDebugService::clsDebugService() { mblnTerminate = false; start(); } /** * @brief clsDebugService::~clsDebugService (Destructor) */ clsDebugService::~clsDebugService() { mblnTerminate = true; terminate(); } /** * @brief clsDebugService::pushDebug * @param strMsg : The message to log */ void clsDebugService::pushDebug(QString strMsg) { if ( strMsg.length() > 0 ) { //Wait for mutex to be available then lock it QMutexLocker lock(clsDebugService::spMutex()); //Insert next sequence number before message if ( msulngDbgSeqNo >= 199 ) { //HACK strMsg += "!!!"; //HACK std::cout << strMsg.toLatin1().data() << std::endl << std::flush; //HACK std::cout << strMsg.length() << std::endl << std::flush; //HACK } //HACK strMsg = QString("S%1 ").arg(++msulngDbgSeqNo, 20, 10, QChar('0')) + strMsg; msStack.push_front(strMsg); } } /** * @brief clsDebugService::run */ void clsDebugService::run() { while ( mblnTerminate == false ) { //Get pointer to class mutex QMutex* pMutex = clsDebugService::spMutex(); //Wait for mutex to be unlocked mWaitCondition.wait(pMutex); //Lock it whilst we access the stack QMutexLocker lock(pMutex); QString strData = clsDebugService::msStack.pop(); if ( strData.isEmpty() == true ) { continue; } std::cout << strData.toLatin1().data() << std::endl << std::flush; } std::cout << "How did I get here?" << std::endl << std::flush; } /** * @brief qDebugMsgHandler * @param type : type of message * @param context : message log context * @param strMsg : message */ static void qDebugMsgHandler(QtMsgType type, const QMessageLogContext& context, const QString& strMsg) { static const QString scstrQJSONObject("QJsonObject("); static const quint16 cuint16InfoLengthLimit = 128; quint16 intMsgLength = static_cast<quint16>(strMsg.length()); quint16 uint16Parts = intMsgLength / cuint16InfoLengthLimit; QString strFile, strFunction, strInfo, strPrefix; long lngLine = 0; switch( type ) { case QtDebugMsg: strPrefix = " Debug:"; break; case QtInfoMsg: strPrefix = " Info:"; break; case QtWarningMsg: strPrefix = " Warning:"; break; case QtCriticalMsg: strPrefix = "Critical:"; break; case QtFatalMsg: strPrefix = " Fatal:"; break; } if ( uint16Parts == 0 ) { uint16Parts = 1; } for( quint16 uint16Part=0; uint16Part<uint16Parts; uint16Part++ ) { QString strOutput(strPrefix) ,strPart = strMsg.mid(uint16Part * cuint16InfoLengthLimit, cuint16InfoLengthLimit); if ( strPart.startsWith(scstrQJSONObject) ) { //Message contains a JSON object, extract the details int intLength = strPart.length() - (scstrQJSONObject.length() + 1); QString strJSON = strPart.mid(scstrQJSONObject.length(), intLength); QJsonDocument objDoc = QJsonDocument::fromJson(strJSON.toUtf8()); if ( objDoc.isNull() ) { return; } QJsonObject objJSON = objDoc.object(); QString strLine(objJSON.take("line").toString()); strFile = objJSON.take("file").toString(); lngLine = strLine.toLong(); strInfo = objJSON.take("msg").toString(); type = static_cast<QtMsgType>(objJSON.take("type").toInt()); } else { strFile = QString(context.file); if ( context.function ) { strFunction = QString(context.function); strFunction = strFunction.mid(0, strFunction.indexOf(clsXMLnode::msccBrktOpen)); } if ( context.line > 0 ) { lngLine = context.line; } strInfo = strPart; } if ( uint16Part == 0 ) { if ( lngLine > 0 ) { strOutput += QString(" L%1:").arg(lngLine, 8, 10, QChar('0')); } if ( strFile.length() > 0 ) { strOutput += strFile + " "; } if ( strFunction.length() > 0 ) { strOutput += strFunction; } if ( strOutput.length() > 0 ) { strOutput += ": "; } clsDebugService::pushDebug(strOutput); clsDebugService::pushDebug(strPrefix + strInfo); } else if ( uint16Parts > 1 ) { strOutput += strInfo; clsDebugService::pushDebug(strOutput); } } } /** * @brief clsDebugService::serviceDebugQueue */ void clsDebugService::serviceDebugQueue() { Q_ASSERT_X(clsDebugService::mspService==nullptr, "clsDebugService" , "Service already started!"); //Install message handler qInstallMessageHandler(qDebugMsgHandler); //Create instance of the service new clsDebugService(); }
The pushDebug method locks a mutex and the thread uses a wait condition on the same mutex to be available then locks it, but it doesn't work, when I launch this it jumps into:
atomic_cxx11.h
template <typename T> static inline T fetchAndAddRelease(std::atomic<T> &_q_value, typename QAtomicAdditiveType<T>::AdditiveT valueToAdd) noexcept { return _q_value.fetch_add(valueToAdd, std::memory_order_release); }
-
@SPlatten
Have you at least verified that if you letcout
/cerr
go to file, you get everything correctly? So that you know it is some console handling issue? And I assumeqDebug()
has the same issue when sent to console? -
@JonB , hello, this is two issues, one with not all the data appearing and the other trying to fix the thread to use QWaitCondition. I'll try writing to a file now and report back when I've done it.
-
@JonB , if I write the entire string to a file:
static FILE* fp = nullptr; void clsDebugService::close() { if ( fp != nullptr ) { fclose(fp); fp = nullptr; } } void clsDebugService::toFile(QString strData) { if ( fp == nullptr ) { fp = fopen("/Users/simonplatten/build-XMLMPAM-Desktop_Qt_5_14_2_clang_64bit-Debug/dump.txt", "wt"); } fputs(strData.toLatin1().data(), fp); fflush(fp); }
After calling this I close the file, the text file contains absolutely everything and is perfect, however if I then use the same routines in my test loop that breaks the string into 80 byte packets I don't get everything in the file. Which to me points to a problem in my loop.
-
@SPlatten said in Class and thread to manage debug output:
This is the new version of the class using a Wait Conditiion and Mutex, it isn't right, can someone help me fix it?
Prototype:
/** * File: clsDebugService.h * Notes: This file contains the prototype for the clsDebugService class. ******************************************************************************* * Class: clsDebugService * * Static Members: * msMutex Mutex * msStack Stack of messages to service * msulngDbgSeqNo Debugging sequence number * * Static Methods: * pushDebug Appends a debug message string to the log * serviceDebugQueue Installs a thread to service the debug stack * spMutex Access method to get address of mutex * * Members: * mblnTerminate true to terminate thread * * Methods: * clsDebugService Class constructor * ~clsDebugService Class destructor * run Thread body ******************************************************************************* * History: 2020/07/16 Created by Simon Platten */ #ifndef CLSDEBUGSERVICE_H #define CLSDEBUGSERVICE_H #include <QStack> #include <QThread> #include <QWaitCondition> class clsDebugService : public QThread { private: static ulong msulngDbgSeqNo; static clsDebugService* mspService; static QStack<QString> msStack; static QMutex msMutex; bool mblnTerminate; QWaitCondition mWaitCondition; void run(); public: explicit clsDebugService(); ~clsDebugService(); static void pushDebug(QString strMsg); static void serviceDebugQueue(); static QMutex* spMutex() { return &msMutex; } }; #endif // CLSDEBUGSERVICE_H
Implementation:
#include <iostream> #include <clsDebugService.h> #include <clsMainWnd.h> //Static members QMutex clsDebugService::msMutex; QStack<QString> clsDebugService::msStack; ulong clsDebugService::msulngDbgSeqNo = 0; clsDebugService* clsDebugService::mspService = nullptr; /** * @brief clsDebugService::clsDebugService */ clsDebugService::clsDebugService() { mblnTerminate = false; start(); } /** * @brief clsDebugService::~clsDebugService (Destructor) */ clsDebugService::~clsDebugService() { mblnTerminate = true; terminate(); } /** * @brief clsDebugService::pushDebug * @param strMsg : The message to log */ void clsDebugService::pushDebug(QString strMsg) { if ( strMsg.length() > 0 ) { //Wait for mutex to be available then lock it QMutexLocker lock(clsDebugService::spMutex()); //Insert next sequence number before message if ( msulngDbgSeqNo >= 199 ) { //HACK strMsg += "!!!"; //HACK std::cout << strMsg.toLatin1().data() << std::endl << std::flush; //HACK std::cout << strMsg.length() << std::endl << std::flush; //HACK } //HACK strMsg = QString("S%1 ").arg(++msulngDbgSeqNo, 20, 10, QChar('0')) + strMsg; msStack.push_front(strMsg); } } /** * @brief clsDebugService::run */ void clsDebugService::run() { while ( mblnTerminate == false ) { //Get pointer to class mutex QMutex* pMutex = clsDebugService::spMutex(); //Wait for mutex to be unlocked mWaitCondition.wait(pMutex); //Lock it whilst we access the stack QMutexLocker lock(pMutex); QString strData = clsDebugService::msStack.pop(); if ( strData.isEmpty() == true ) { continue; } std::cout << strData.toLatin1().data() << std::endl << std::flush; } std::cout << "How did I get here?" << std::endl << std::flush; } /** * @brief qDebugMsgHandler * @param type : type of message * @param context : message log context * @param strMsg : message */ static void qDebugMsgHandler(QtMsgType type, const QMessageLogContext& context, const QString& strMsg) { static const QString scstrQJSONObject("QJsonObject("); static const quint16 cuint16InfoLengthLimit = 128; quint16 intMsgLength = static_cast<quint16>(strMsg.length()); quint16 uint16Parts = intMsgLength / cuint16InfoLengthLimit; QString strFile, strFunction, strInfo, strPrefix; long lngLine = 0; switch( type ) { case QtDebugMsg: strPrefix = " Debug:"; break; case QtInfoMsg: strPrefix = " Info:"; break; case QtWarningMsg: strPrefix = " Warning:"; break; case QtCriticalMsg: strPrefix = "Critical:"; break; case QtFatalMsg: strPrefix = " Fatal:"; break; } if ( uint16Parts == 0 ) { uint16Parts = 1; } for( quint16 uint16Part=0; uint16Part<uint16Parts; uint16Part++ ) { QString strOutput(strPrefix) ,strPart = strMsg.mid(uint16Part * cuint16InfoLengthLimit, cuint16InfoLengthLimit); if ( strPart.startsWith(scstrQJSONObject) ) { //Message contains a JSON object, extract the details int intLength = strPart.length() - (scstrQJSONObject.length() + 1); QString strJSON = strPart.mid(scstrQJSONObject.length(), intLength); QJsonDocument objDoc = QJsonDocument::fromJson(strJSON.toUtf8()); if ( objDoc.isNull() ) { return; } QJsonObject objJSON = objDoc.object(); QString strLine(objJSON.take("line").toString()); strFile = objJSON.take("file").toString(); lngLine = strLine.toLong(); strInfo = objJSON.take("msg").toString(); type = static_cast<QtMsgType>(objJSON.take("type").toInt()); } else { strFile = QString(context.file); if ( context.function ) { strFunction = QString(context.function); strFunction = strFunction.mid(0, strFunction.indexOf(clsXMLnode::msccBrktOpen)); } if ( context.line > 0 ) { lngLine = context.line; } strInfo = strPart; } if ( uint16Part == 0 ) { if ( lngLine > 0 ) { strOutput += QString(" L%1:").arg(lngLine, 8, 10, QChar('0')); } if ( strFile.length() > 0 ) { strOutput += strFile + " "; } if ( strFunction.length() > 0 ) { strOutput += strFunction; } if ( strOutput.length() > 0 ) { strOutput += ": "; } clsDebugService::pushDebug(strOutput); clsDebugService::pushDebug(strPrefix + strInfo); } else if ( uint16Parts > 1 ) { strOutput += strInfo; clsDebugService::pushDebug(strOutput); } } } /** * @brief clsDebugService::serviceDebugQueue */ void clsDebugService::serviceDebugQueue() { Q_ASSERT_X(clsDebugService::mspService==nullptr, "clsDebugService" , "Service already started!"); //Install message handler qInstallMessageHandler(qDebugMsgHandler); //Create instance of the service new clsDebugService(); }
The pushDebug method locks a mutex and the thread uses a wait condition on the same mutex to be available then locks it, but it doesn't work, when I launch this it jumps into:
atomic_cxx11.h
template <typename T> static inline T fetchAndAddRelease(std::atomic<T> &_q_value, typename QAtomicAdditiveType<T>::AdditiveT valueToAdd) noexcept { return _q_value.fetch_add(valueToAdd, std::memory_order_release); }
Can anyone help me with this?
-
@SPlatten said in Class and thread to manage debug output:
//Get pointer to class mutex QMutex* pMutex = clsDebugService::spMutex(); //Wait for mutex to be unlocked mWaitCondition.wait(pMutex); //Lock it whilst we access the stack QMutexLocker lock(pMutex);
You must lock the mutex before you call
wait()
, and you must not re-lock it after the wait. See the documentation: https://doc.qt.io/qt-5/qwaitcondition.html#wait-2 (Note: The same concept applies tostd::condition_variable
andboost::condition_variable
. You might want to review your existing projects that use condition variables.){ pMutex->lock(); mWaitCondition.wait(pMutex); /* Do work on the stack here */ pMutex->unlock(); }
-
@JKSH , I'm not sure what I'm missing but I just don't seem to be able to get this to work.
-
@SPlatten said in Class and thread to manage debug output:
I'm not sure what I'm missing but I just don't seem to be able to get this to work.
Get which part to work?
Please post a minimal compilable example that contains the issue
-
@JKSH , to be honest I'm not sure if it was my implementation (probably) as I'm not sure I understand how it works:
My thread loop:
QMutex* pMutex = clsDebugService::spMutex(); while ( mblnTerminate == false ) { mWaitCondition.wait(pMutex); pMutex->lock(); //... pMutex->unlock(); }
Then in another function which pushes content onto a stack which the thread is supposed to service:
void clsDebugService::pushDebug(QString strMsg) { if ( strMsg.length() > 0 ) { //Wait for mutex to be available then lock it QMutexLocker lock(clsDebugService::spMutex()); //Insert next sequence number before message strMsg = QString("S%1 ").arg(++msint64DbgSeqNo, 20, 10, QChar('0')) + strMsg; msStack.push_front(strMsg); } }
-
@SPlatten said in Class and thread to manage debug output:
@JKSH , to be honest I'm not sure if it was my implementation (probably) as I'm not sure I understand how it works:
My thread loop:
QMutex* pMutex = clsDebugService::spMutex(); while ( mblnTerminate == false ) { mWaitCondition.wait(pMutex); pMutex->lock(); //... pMutex->unlock(); }
As I wrote yesterday, you must lock the mutex before you call
wait()
. The same rule applies to QWaitCondition, std::condition_variable, and boost:condition_variable.wait()
unlocks the mutex while waiting and then re-locks it again before allowing your code to run. -
@JKSH , ok, but this is where I am a little confused, what does a wait add? because using mutex'es and lock, causes the lock function to wait until it is unlocked.
-
@SPlatten said in Class and thread to manage debug output:
what does a wait add? because using mutex'es and lock, causes the lock function to wait until it is unlocked.
While a thread is waiting, the mutex is unlocked so that other threads can use the mutex.
This might be useful: https://stackoverflow.com/questions/31913547/how-do-stdunique-lock-and-stdcondition-variable-work
-
I am on Ubuntu 16
I first noticed this when I codded just four < 16 characters long test cout /cerr messages in a sequence.
I have not paid much attention to what C++ I am using on Qt, I got bigger problems than to worry about C/C++.However, made en error
std:cout <<... << endl;
missed std:: before endl
it complied, run AND
got some strange warning.
Then each message got extra "1" character at the end.Here is anther example of "timing cout /cerr "
CODE :
#ifdef TRACE
std::cerr << "@file @function @line " <<FILE<< " "<< FUNCTION << " " << LINE << " "<< std::endl;
#endif#ifdef TRACE
std::cout << "@file @function @line " <<FILE<< " "<< FUNCTION << " " << LINE << " "<< std::endl;
#endif
#ifdef TRACE
std::cout << "@file @function @line " <<FILE<< " "<< FUNCTION << " " << LINE << " "<< std::endl;
#endif
#ifdef TRACE
std::cout << "@file @function @line " <<FILE<< " "<< FUNCTION << " " << LINE << " "<< std::endl;
#endif
#ifdef TRACE
std::cerr << "@file @function @line " <<FILE<< " "<< FUNCTION << " " << LINE << " "<< std::endl;
#endifOUTPUT:
CONSTRUCTOR @file @function @line ../../../examples/bluetooth/btscanner/tabwidget.cpp TabWidget 14
output from cerr
@file @function @line ../../../examples/bluetooth/btscanner/tabwidget.cpp on_scan_pressed 37
@file @function @line ../../../examples/bluetooth/btscanner/tabwidget.cpp on_scan_pressed 51ouptut from cout
@file @function @line ../../../examples/bluetooth/btscanner/tabwidget.cpp on_scan_pressed 42
@file @function @line ../../../examples/bluetooth/btscanner/tabwidget.cpp on_scan_pressed 45
@file @function @line ../../../examples/bluetooth/btscanner/tabwidget.cpp on_scan_pressed 48Note the "lines" sequence.
I had some sucess adding flush() after cout , which acording to spec is not necessry since cout inlcudes flush.