Class and thread to manage debug output

SPlatten

I've written a helper class to manage the qDebug() output during debugging and development of my application, the intention is for this to manage writing of sometimes large amounts of data.

Here is the class prototype, clsDebugService.h:

/**
 * File:    clsDebugService.h
 * Notes:   This file contains the prototype for the clsDebugService class.
 *******************************************************************************
 * Class:   clsDebugService
 *
 * Static Members:
 *  mscuintInterval   Millisecond interval between thread iterations
 *  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
 *
 * 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>

    class clsDebugService : public QThread {
    private:
        static const uint mscuintInterval;
        static ulong msulngDbgSeqNo;
        static clsDebugService* mspService;
        static QStack<QString> msStack;

        bool mblnTerminate;

        void run();

    public:
        explicit clsDebugService();
        ~clsDebugService();

        static void pushDebug(QString strMsg);
        static void serviceDebugQueue();
    };
#endif // CLSDEBUGSERVICE_H

Here is the implementation:

#include <iostream>

#include <clsDebugService.h>
#include <clsMainWnd.h>
//Static members
QStack<QString> clsDebugService::msStack;
ulong clsDebugService::msulngDbgSeqNo = 0;
const uint clsDebugService::mscuintInterval = 60;
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 ) {
//Insert next sequence number before message
        strMsg = QString("S%1 ").arg(++msulngDbgSeqNo, 20, 10, QChar('0')) + strMsg;
        msStack.push_front(strMsg);
    }
}

/**
 * @brief clsDebugService::run
 */
void clsDebugService::run() {
    while ( mblnTerminate == false ) {
        QThread::msleep(mscuintInterval);

        if ( msStack.length() == 0 ) {
            continue;
        }
        QString strMsg = msStack.pop();

        if ( strMsg.length() > 0 ) {
            std::cout << strMsg.toLatin1().data() << 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);
            continue;
        }
        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();
}

Typical output to the Application Output will look like this:

S00000000000000000001    Debug: L00000734:../XMLMPAM/clsMainWnd.cpp clsXMLnode::clsXMLnode: 
S00000000000000000002    Debug:PROCESSING SUBSCRIPTION "clicked" "win1" "simon2.js@buttonHandler"

The S number is the sequence number, then the type of message, in this example "Debug", the L number is the line number followed by the source path and file name then the class and/or function name. Then following lines are the actual content written to qDebug() prefixed with a sequence number.
The service is installed in main like this:

//Install custom message handler
clsDebugService::serviceDebugQueue();

The problem I'm having is that the class uses a QString Stack to manage messages written. The Stack is then serviced by a thread installed by this class which pops of messages from the stack, the delay between each pop is determine by the millisecond delay "mscuintInterval" which is 60 milliseconds.

When my application starts up there are 176 messages written to qDebug and I can see all of these in the Application Output, none of these messages are larger than 160 bytes.

The issue I'm having is that there is one particular JSON message than is encoded as a string and then sent to qDebug(), for reasons which I don't understand not everything makes it out of the stack.

I write in 2865 bytes as a single string:

qDebug() << strJSON;

I've worked out what the sequence number will be when it gets to the end of this content as 199, by inserting temporary code I trap this sequence number and append !!! to the message, this is done in the pushDebug function:

void clsDebugService::pushDebug(QString strMsg) {
    if ( strMsg.length() > 0 ) {
//Insert next sequence number before message
        if ( msulngDbgSeqNo >= 199 ) {
            strMsg += "!!!";
            std::cout << strMsg.toLatin1().data() << std::endl << std::flush;
            std::cout << strMsg.length() << std::endl << std::flush;
        }
        strMsg = QString("S%1 ").arg(++msulngDbgSeqNo, 20, 10, QChar('0')) + strMsg;
        msStack.push_front(strMsg);
    }
}

Looking in the debugger the message does contain the end of the message and does have the "!!!" in the correct position. However the problem is that looking at the Application Output I do not see the entire JSON output that was written into the queue and the !!! is not in the same place it was when it was appended.

Any suggestions will be taken seriously and I would be very grateful for any help anyone can offer.

SGaist

Hi,

I haven't done a deep analysis of your code but from a cursory look, you are going to burn cpu cycles for not much benefit with your busy loop. Why not use a QWaitCondition ?

SPlatten

@SGaist Thank you, I'll look into it.

I've just added the following to my application:

static bool blnDoOnce = false;
falseif ( blnDoOnce == false ) {
false    const char marker[] = "border: 1px solid #ff0000;";
false    int intPos = strScriptWithCall.indexOf(marker) + strlen(marker);
false    std::cout << "strScriptWithCall.length: " << strScriptWithCall.length() << std::endl << std::flush;
false    std::cout << "  written with std::cout: " << intPos << std::endl << std::flush;
false    std::cout << "              difference: " << (strScriptWithCall.length() - intPos) << std::endl << std::flush;
false    std::cout << strScriptWithCall.toLatin1().data() << std::endl << std::flush;
false    blnDoOnce = true;
false}

The above code was written this way because the output in the Application Console shows:

strScriptWithCall.length: 2865
  written with std::cout: 929
              difference: 1936
function dumpObj(obj, key, level) { if ( typeof obj == "undefined" ) { return; } if ( typeof level == "undefined" ) { level = 0; } if ( typeof key == "undefined" ) { key = ""; } var strIndent = ""; for( var l=1; l<level; l++ ) { strIndent += " "; } if ( typeof obj == "object" ) { for( var a in obj ) { dumpObj(obj[a], a, level); } level++; } else { xmleng.log(strIndent + key + "(" + (typeof obj) + "): " + obj, "simon2.js", 22); } } function setWinTitle(objJSON) { xmleng.log("----- setWinTitle() -----", "simon2.js", 26); if ( typeof objJSON == "object" && typeof objJSON["sid"] == "string" && typeof objJSON["text"] == "string" ) { var slstIDandAttr = objJSON["sid"].split(":"); if ( slstIDandAttr.length == 2 ) { var strTargetID = slstIDandAttr[0]; xmleng.setAttribute(strTargetID, "title", objJSON["text"]); } xmleng.setAttribute("btn1", "properties", "QPushButton {background-color: #eea6c1;" + "border: 1px solid #ff0000;

strScriptWithCall contains a lot more data than has actually been written, the difference shows the output is short by 1936 bytes.

It seems that what is sent to std::cout is limit and despite putting a flush at the end of the line it doesn't help. What have I done wrong and how can I fix it?

SPlatten

@SGaist I haven't used QWaitCondition before, is there an example of how I can use it to cause my thread to wait until there is something to do?

JKSH

@SPlatten said in Class and thread to manage debug output:

I haven't used QWaitCondition before, is there an example of how I can use it to cause my thread to wait until there is something to do?

Use it like boost::condition_variable: https://forum.qt.io/topic/117174/equivalent-to-boost-condition_variable

SPlatten

This post is deleted!

AnneRanch

@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.

SPlatten

@AnneRanch thank you, what operating system are you using?

I am developing on an iMAC running:

macOS Catalina
Version 10.15.6

JonB

@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 flush cout.

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?

SPlatten

@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.

SPlatten

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);
    }

JonB

@SPlatten
Have you at least verified that if you let cout/cerr go to file, you get everything correctly? So that you know it is some console handling issue? And I assume qDebug() has the same issue when sent to console?

SPlatten

@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.

SPlatten

@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

@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?

JKSH

@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 to std::condition_variable and boost::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();
}

SPlatten

@JKSH , I'm not sure what I'm missing but I just don't seem to be able to get this to work.

JKSH

@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

SPlatten

@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);
    }
}

JKSH

@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.

SPlatten

@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.

JKSH

@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

AnneRanch

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;
#endif

OUTPUT:

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 51

ouptut 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 48

Note the "lines" sequence.

I had some sucess adding flush() after cout , which acording to spec is not necessry since cout inlcudes flush.

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

Class and thread to manage debug output