Class and thread to manage debug output

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