Important: Please read the Qt Code of Conduct - https://forum.qt.io/topic/113070/qt-code-of-conduct

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 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:


Log in to reply