Unsolved Debug output thread
-
I've posted about this before and it was working ok, but today I revisited it and have manage to break it.
I have a class that manages the debug output for my application, prototype:
/** * File: clsDebugService.h * Notes: This file contains the prototype for the clsDebugService class. ******************************************************************************* * Class: clsDebugService * * Static Members: * msblnAutoFileName true if automatic file naming else false * msblnToConsole true to output to console else false, default=false * msblnToFile true to output to file else false, default=false * msccBrktClose ')' * msccBrktOpen '(' * msccDebugLevelDelimiter ~ * msccPrefixCritical Prefix for critical error message * msccPrefixDebug Prefix for debug message * msccPrefixFatal Prefix for fatal error message * msccPrefixInfo Prefix for info. message * msccPrefixWarning Prefix for warning message * msccSpace ' ' * mscintDefaultLevel Only messages < than this level are logged * mscintLineNoLength Line number field length * mscintLineNoBase Line number field base * mscintSeqNoLength Sequence number field length * mscintSeqNoBase Sequence number field base * mscuint16ThreadFrequency Thread run frequency * msintDebugPrefixLength Length of debug msg prefix * msint64DbgSeqNo Debugging sequence number * msint64FileSizeLimit Limit on file * mspService Pointer to service * msMutex Mutex to maintain synchronisation * msuint8PartNumber Part number used for auto generated files * msFile Current file * msslstPrefixes Recognized prefixes * msStack Stack of messages to service * msstrFile File name where message originates from * msuint32Line Line number where message originates from * * Static Methods: * blnAutoFileName Access method to return msblnAutoFileName * consoleLogging Access method to turn on/off console logging * exitWhenDebugQueueEmpty Exit application after debug queue empties * fileLogging Access method to turn on/off file logging * intMsgPrefixLength Access method to return msintDebugPrefixLength * pGetService Access method to return mspService * pushDebug Appends a debug message string to the log * serviceDebugQueue Installs a thread to service the debug stack * setFileName Access method to set the file name * strFileName Access method to get the file name * strGetUserFolder Get or Make folder with user folder * * Members: * mblnAutofilename default is true if file name not set * mblnTerminate true to terminate thread * mstrFilename Current filename * mstrPrefix File name prefix * * 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 <QDebug> #include <QDir> #include <QFile> #include <QStack> #include <QThread> #include <QWaitCondition> #include <wordexp.h> class clsDebugService : public QThread { Q_OBJECT private: static bool msblnAutoFileName, msblnToConsole, msblnToFile; static quint16 mscuint16ThreadFrequency; static int msintDebugPrefixLength; static qint64 msint64DbgSeqNo; static qint64 msint64FileSizeLimit; static std::mutex msMutex; static qint8 msuint8PartNumber; static QDir msDir; static QFile msFile; static QStringList msslstPrefixes; static clsDebugService* mspService; static QStack<QString> msStack; bool mblnTerminate; QString mstrFilename, mstrPrefix; void run(); public: static const QChar msccBrktClose ,msccBrktOpen ,msccDebugLevelDelimiter ,msccPrefixCritical ,msccPrefixDebug ,msccPrefixFatal ,msccPrefixInfo ,msccPrefixWarning ,msccSpace; static const int mscintDefaultLevel ,mscintLineNoLength ,mscintLineNoBase ,mscintSeqNoLength ,mscintSeqNoBase; explicit clsDebugService(QString strPrefix = "", bool blnToConsole = false, bool blnOutToFile = false); ~clsDebugService(); static bool blnAutoFileName() { return clsDebugService::msblnAutoFileName; } static void consoleLogging(bool blnOn) { clsDebugService::msblnToConsole = blnOn; } static void exitWhenDebugQueueEmpty(QString strMsg); static void fileLogging(bool blnOn) { clsDebugService::msblnToFile = blnOn; } static int intMsgPrefixLength() { return clsDebugService::msintDebugPrefixLength; } static clsDebugService* pGetService() { return clsDebugService::mspService; } static void pushDebug(QString strMsg); static void serviceDebugQueue(QString strPrefix = "", bool blnToConsole = false, bool blnOutToFile = false); static void setFilename(QString strFileName); static QString strFileName() { return msFile.fileName(); } static QString strGetUserFolder(QString strFolder); static QString msstrFile; static uint32_t msuint32Line; }; //Macro to condense the debug statement #define qdbg() qDebug().noquote().nospace() #endif // CLSDEBUGSERVICE_H
Implementation:
#include <errno.h> #include <iostream> #include <QDate> #include <QJsonDocument> #include <QJsonObject> #include <QTextStream> #include "clsDebugService.h" //Static members bool clsDebugService::msblnAutoFileName = true; bool clsDebugService::msblnToConsole = false; bool clsDebugService::msblnToFile = false; const QChar clsDebugService::msccBrktClose(')') ,clsDebugService::msccBrktOpen('(') ,clsDebugService::msccDebugLevelDelimiter(0x02) ,clsDebugService::msccPrefixCritical('C') ,clsDebugService::msccPrefixDebug('D') ,clsDebugService::msccPrefixFatal('F') ,clsDebugService::msccPrefixInfo('I') ,clsDebugService::msccPrefixWarning('W') ,clsDebugService::msccSpace(' '); const int clsDebugService::mscintDefaultLevel = 2 ,clsDebugService::mscintLineNoLength = 8 ,clsDebugService::mscintLineNoBase = 10 ,clsDebugService::mscintSeqNoLength = 20 ,clsDebugService::mscintSeqNoBase = 10; quint16 clsDebugService::mscuint16ThreadFrequency = 100; int clsDebugService::msintDebugPrefixLength = 0; QDir clsDebugService::msDir(QDir::currentPath()); QFile clsDebugService::msFile; QStack<QString> clsDebugService::msStack; qint64 clsDebugService::msint64DbgSeqNo = 0 ,clsDebugService::msint64FileSizeLimit = 720 * 1024; std::mutex clsDebugService::msMutex; qint8 clsDebugService::msuint8PartNumber = 1; clsDebugService* clsDebugService::mspService = nullptr; QString clsDebugService::msstrFile; QStringList clsDebugService::msslstPrefixes; uint32_t clsDebugService::msuint32Line; /** * @brief clsDebugService::clsDebugService * @param strPrefix : Optional, default is "" * @param blnOutToConsole : Optional, default is false * @param blnOutToFile : Optional, default is false */ clsDebugService::clsDebugService(QString strPrefix, bool blnOutToConsole, bool blnOutToFile) : mblnTerminate(false) , mstrPrefix(strPrefix) { Q_ASSERT_X(clsDebugService::mspService==nullptr, "clsDebugService" , "Service already started!"); clsDebugService::consoleLogging(blnOutToConsole); clsDebugService::fileLogging(blnOutToFile); clsDebugService::mspService = this; start(); } /** * @brief clsDebugService::~clsDebugService (Destructor) */ clsDebugService::~clsDebugService() { mblnTerminate = true; terminate(); } /** * @brief clsDebugService::exitWhenDebugQueueEmpty * @param strMsg : Message to log */ void clsDebugService::exitWhenDebugQueueEmpty(QString strMsg) { { std::unique_lock<std::mutex> lock(msMutex); //Clear out the queue msStack.empty(); } pushDebug(strMsg + strerror(errno)); //Wait for message to be processed bool blnDone = false; do { std::unique_lock<std::mutex> lock(msMutex); blnDone = msStack.isEmpty(); } while( blnDone == false ); //Terminate application std::exit(EXIT_FAILURE); } /** * @brief clsDebugService::pushDebug * @param strMsg : The message to log */ void clsDebugService::pushDebug(QString strMsg) { if ( strMsg.isEmpty() ) { return; } if ( clsDebugService::msslstPrefixes.length() == 0 ) { clsDebugService::msslstPrefixes << clsDebugService::msccPrefixCritical << clsDebugService::msccPrefixDebug << clsDebugService::msccPrefixFatal << clsDebugService::msccPrefixInfo << clsDebugService::msccPrefixWarning; } QString strPrefix = strMsg.mid(0, 1); if ( msslstPrefixes.indexOf(strPrefix) >= 0 ) { strMsg = strMsg.mid(1); } else { strPrefix = clsDebugService::msccPrefixInfo; } //Insert next sequence number before message strPrefix += QString("%1:").arg(++msint64DbgSeqNo ,clsDebugService::mscintSeqNoLength ,clsDebugService::mscintSeqNoBase, QChar('0')); if ( clsDebugService::msintDebugPrefixLength == 0 ) { clsDebugService::msintDebugPrefixLength = strPrefix.length(); } //Wait for mutex to be available then lock it { std::unique_lock<std::mutex> lock(msMutex); msStack.push_front(strPrefix + strMsg); } } /** * @brief clsDebugService::setFilename * @param strFileName : filename to use */ void clsDebugService::setFilename(QString strFileName) { if ( strFileName.isEmpty() != true ) { clsDebugService::msblnAutoFileName = false; clsDebugService::msFile.setFileName(strFileName); } } /** * @brief clsDebugService::run */ void clsDebugService::run() { QString strData, strPath(clsDebugService::strGetUserFolder("~")); while ( mblnTerminate == false ) { QThread::msleep(clsDebugService::mscuint16ThreadFrequency); { //Anything on the stack? std::unique_lock<std::mutex> lock(msMutex); if ( clsDebugService::msStack.length() > 0 ) { strData = clsDebugService::msStack.pop(); } if ( strData.isEmpty() == true ) { continue; } } QStringList slstLines = strData.split("\n"); strData = ""; //+2 to allow for type prefix and colon QString strPadding(" "); strPadding = strPadding.repeated(clsDebugService::mscintSeqNoLength + 2); uint16_t uint16Line = 1; foreach( QString strLine, slstLines ) { if ( uint16Line++ > 1 ) { //Insert padding at the front of additional lines strLine = strPadding + strLine; } if ( clsDebugService::msblnToFile == true ) { bool blnOpen; if ( clsDebugService::blnAutoFileName() == true ) { QChar qcPadding('0'), qcSeperator(QDir::separator()); QDate dtNow(QDate::currentDate()); int intBase(10), intYear(dtNow.year()), intMonth(dtNow.month()), intDay(dtNow.day()); //Generate file name using year, month, day QString strExisting = clsDebugService::msFile.fileName() ,strFileName = QString("%1%2%3%4").arg(mstrPrefix) .arg(intYear, 4, intBase, qcPadding) .arg(intMonth, 2, intBase, qcPadding) .arg(intDay, 2, intBase, qcPadding); //Is file open and is the size greater than the limit? if ( (blnOpen = clsDebugService::msFile.isOpen()) == true && clsDebugService::msFile.size() > clsDebugService::msint64FileSizeLimit ) { //Increment part number clsDebugService::msuint8PartNumber++; } if ( blnOpen == true ) { //Get just the file name int intFile = strExisting.lastIndexOf(qcSeperator); strExisting = strExisting.mid(intFile + 1); //Remove the extension strExisting = strExisting.mid(0, strExisting.indexOf(".")); } if ( blnOpen != true || strExisting.compare(strFileName) != 0 ) { if ( blnOpen == true ) { clsDebugService::msFile.close(); blnOpen = false; } clsDebugService::msuint8PartNumber = 1; } //Append part number if ( blnOpen != true ) { clsDebugService::msFile.setFileName(strPath + strFileName + QString(".%1") .arg(clsDebugService::msuint8PartNumber, 3, intBase, qcPadding)); } } //Is file open? if ( (blnOpen = clsDebugService::msFile.isOpen()) != true ) { clsDebugService::msFile.open(QIODevice::WriteOnly | QIODevice::Text); blnOpen = clsDebugService::msFile.isOpen(); } if ( blnOpen == true ) { QTextStream tsText(&clsDebugService::msFile); tsText << strLine.toLatin1().data() << "\r\n"; } } if ( clsDebugService::msblnToConsole == true ) { //Output to console std::cout << strLine.toLatin1().data() << "\n"; std::cout << std::flush; } } } std::cout << "HERE!!!" << std::endl; } /** * @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 QChar qcCarriageReturn('\n') ,qcCloseBracket(')') ,qcComma(',') ,qcOpenBracket('('); static QString sstrLastFile, sstrLastFunction; static long slngLastLine = -1; quint16 uint16DebugLevel = clsDebugService::mscintDefaultLevel ,uint16MsgOffset; QString strFile, strFunction, strInfo, strPrefix; int intLevelDelimiterIdx = -1; long lngLine = 0; //Look for debug level delimiter: \x2, NOTE we cannot use indexOf to locate it! static const char ccDebugLevelDelimiter = (clsDebugService::msccDebugLevelDelimiter.toLatin1() + '0'); for( int i=0; i<strMsg.length() - 3; i++ ) { if ( strMsg[i + 1].toLatin1() == '\\' && strMsg[i + 2].toLatin1() == 'x' && strMsg[i + 3].toLatin1() == ccDebugLevelDelimiter ) { intLevelDelimiterIdx = ++i; break; } } if ( intLevelDelimiterIdx > 0 ) { //Yes, its the debug level uint16DebugLevel = strMsg.mid(0, intLevelDelimiterIdx).toUInt(); //Offset to start of message uint16MsgOffset = intLevelDelimiterIdx + 3; } else { uint16MsgOffset = 0; } if ( uint16DebugLevel > clsDebugService::mscintDefaultLevel ) { //Do nothing debug level is higher than this messages level return; } switch( type ) { case QtCriticalMsg: strPrefix = "C"; break; case QtDebugMsg: strPrefix = "D"; break; case QtFatalMsg: strPrefix = "F"; break; case QtInfoMsg: strPrefix = "I"; break; case QtWarningMsg: strPrefix = "W"; break; } //Split message into lines? QStringList slstParts = strMsg.mid(uint16MsgOffset).split(qcCarriageReturn); quint16 uint16Parts = slstParts.length(); for( quint16 uint16Part=0; uint16Part<uint16Parts; uint16Part++ ) { QString strOutput, strPart; if ( slstParts.length() > 1 ) { strPart = slstParts[uint16Part]; if ( strPart.startsWith(qcComma) ) { strPart = strPart.remove(qcComma); } if ( uint16Part == 0 && strPart.startsWith(qcOpenBracket) ) { strPart = clsDebugService::msccSpace + strPart.mid(1); } if ( uint16Part == uint16Parts && strPart.endsWith(qcCloseBracket) ) { strPart = strPart.remove(qcCloseBracket); } } else { strPart = slstParts[uint16Part]; } if ( strPart.isEmpty() == true ) { continue; } 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 = clsDebugService::msstrFile; lngLine = static_cast<long>(clsDebugService::msuint32Line); if ( context.function ) { strFunction = QString(context.function); strFunction = strFunction.mid(0, strFunction.indexOf(clsDebugService::msccBrktOpen)); } strInfo = strPart; } if ( (strInfo = strInfo.trimmed()).isEmpty() == true ) { continue; } if ( uint16Part == 0 ) { if ( lngLine > 0 && !(slngLastLine == lngLine && strFile.compare(sstrLastFile) == 0 && sstrLastFunction.compare(strFunction) == 0) ) { sstrLastFile = strFile; slngLastLine = lngLine; sstrLastFunction = strFunction; strOutput = QString("L%1").arg(lngLine, clsDebugService::mscintLineNoLength , clsDebugService::mscintLineNoBase, QChar('0')); if ( strFile.length() > 0 ) { strOutput += QString("F%1").arg(strFile); } strOutput += "["; if ( strFunction.length() > 0 ) { strOutput += strFunction; } strOutput += "]"; if ( strOutput.length() > 0 ) { strOutput += ":"; } } if ( strOutput.isEmpty() != true ) { clsDebugService::pushDebug(strPrefix + strOutput); } clsDebugService::pushDebug(strPrefix + strInfo); } else if ( uint16Parts > 1 ) { strOutput += strInfo; clsDebugService::pushDebug(strPrefix + strOutput); } } } /** * @brief clsDebugService::serviceDebugQueue * @param strPrefix : Optional, default is "" * @param blnOutToConsole : Optional, default is false * @param blnOutToFile : Optional, default is false */ void clsDebugService::serviceDebugQueue(QString strPrefix, bool blnToConsole, bool blnOutToFile) { Q_ASSERT_X(clsDebugService::mspService==nullptr, "clsDebugService" , "Service already started!"); //Install message handler qInstallMessageHandler(qDebugMsgHandler); //Create instance of the service new clsDebugService(strPrefix, blnToConsole, blnOutToFile); } /** * @brief clsDebugService::strGetUserFolder * @param strFolder : Folder to modify * @return Logged in users folder */ QString clsDebugService::strGetUserFolder(QString strFolder) { const QChar cqcSeperator(QDir::separator()); QByteArray baFullPath(strFolder.toLatin1()); char* pszFullPath = baFullPath.data(); //Ensure path is correct before use, this will handle translation of ~ if used! wordexp_t exp_result; wordexp(pszFullPath, &exp_result, 0); pszFullPath = exp_result.we_wordv[0]; QString strFullPath(pszFullPath); QFileInfo info(strFullPath); if ( info.isDir() == true ) { if ( strFullPath.endsWith(cqcSeperator) != true ) { //Ensure path does not contain a file name? if ( strFullPath.indexOf(".") == -1 ) { strFullPath += cqcSeperator; } } } return strFullPath; }
Typically this produces output to a file and console, something like:
D00000000000000000001:XMLMPAM is listening on: 192.168.1.158:8123 D00000000000000000002:../clsMainWnd.cpp4496HELLO WORLD HACK! D00000000000000000003:L00000151Fsimon.js[void clsScriptHelper::log]: D00000000000000000004:************** setup **************** D00000000000000000005:L00000126Fsimon.js[void clsScriptHelper::log]: D00000000000000000006:************** connect **************** D00000000000000000007:L00000062Fsimon.js[void clsScriptHelper::log]: D00000000000000000008:************** onConnect ************** D00000000000000000009:L00000042Fsimon.js[void clsScriptHelper::log]: D00000000000000000010:************** onRowResults *********** D00000000000000000011:L00000047Fsimon.js[void clsScriptHelper::log]: D00000000000000000012:[0][biPri] : 1 D00000000000000000013:[0][dtWhen] : 2020-11-17 D00000000000000000014:[0][tmWhen] : 08:45:57 D00000000000000000015:[1][biPri] : 2 D00000000000000000016:[1][dtWhen] : 2020-11-17 D00000000000000000017:[1][tmWhen] : 08:49:16
Today I added:
QThread::exec();
After:
QThread::msleep(clsDebugService::mscuint16ThreadFrequency);
And this breaks it completely, the output is reduced to just:
13:57:14: Debugging starts 2020-11-17 13:57:19.987845+0000 XMLMPAM[12334:274739] SecTaskLoadEntitlements failed error=22 cs_flags=20, pid=12334 2020-11-17 13:57:19.987887+0000 XMLMPAM[12334:274739] SecTaskCopyDebugDescription: XMLMPAM[12334]/0#-1 LF=0 2020-11-17 13:57:20.433823+0000 XMLMPAM[12334:274739] SecTaskLoadEntitlements failed error=22 cs_flags=20, pid=12334 2020-11-17 13:57:20.433891+0000 XMLMPAM[12334:274739] SecTaskCopyDebugDescription: XMLMPAM[12334]/0#-1 LF=0
Why ?
-
@SPlatten said in Debug output thread:
today I added:
QThread::exec();
After:
QThread::msleep(clsDebugService::mscuint16ThreadFrequency);And this breaks it completely,
Why ?Because, what you are doing does not make sense!
As written in documentation,QThread::exec()
will start the event loop processing, but with your thread implementation this does not make sense!
In yourrun()
you have a kind of "forever()" loop. So no chance to enter event loop processing!Please take time to understand how threads are used with Qt, to not always made same nonsense implementations: