Debug output thread

[SPlatten]

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 ?

[KroMignon]

@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 your run() 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:

• https://doc.qt.io/qt-5/qthread.html#details
• https://mayaposch.wordpress.com/2011/11/01/how-to-really-truly-use-qthreads-the-full-explanation/
• http://blog.debao.me/2013/08/how-to-use-qthread-in-the-right-way-part-1/
• http://blog.debao.me/2013/08/how-to-use-qthread-in-the-right-way-part-2/