Class and thread to manage debug output

[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

[Anonymous_Banned275]

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.