Diagnosing problem.

[SPlatten]

I have an application that communicates with other applications using sockets, these applications output to the same file. I have defined macros that I use everywhere:

    #define qcrt()      qCritical().noquote().nospace()
    #define qdbg()      qDebug().noquote().nospace()
    #define qinf()      qInfo().noquote().nospace()
    #define qwrn()      qWarning().noquote().nospace()

Typical use:

qdbg() << "HELLO WORLD";

Each application setsup debug handling using qInstallMessageHandler, I give each application an alias according to its purpose. The handler I register:

static void qDebugMsgHandler(QtMsgType type, const QMessageLogContext& context
                                           , const QString& strMsg) {
    clsDebugService* pService(clsDebugService::pGetService());
    if ( pService == nullptr ) {
    //Shouldn't get here...
        return;
    }    
    static const QChar scqcCarriageReturn('\n')
                      ,scqcCloseBracket(')')
                      ,scqcComma(',')
                      ,scqcOpenBracket('(');
    static QString sstrLastFile, sstrLastFunction;
    static long slngLastLine(-1);
    quint16 uint16DebugLevel(clsDebugService::mscintDefaultLevel);
    QString strFile, strFunction, strOutput;
    bool blnSuppressPrefixes(false);
    int intLevelLength(-1);
    //Look for debug level delimiter: \x2, NOTE we cannot use indexOf to locate it!
    static const char ccDebugLevelDelimiter(clsDebugService::msccDebugLevelDelimiter.toLatin1() + '0');
    static const char ccSuppressDebugPrefix(clsDebugService::msccSuppressDebugPrefix.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 ) {
            int intMsgStart(i + 4);
            intLevelLength = i + 1;
            if ( strMsg[i + 4].toLatin1() == '\\'
              && strMsg[i + 5].toLatin1() == 'x'
              && strMsg[i + 6].toLatin1() == ccSuppressDebugPrefix ) {
                blnSuppressPrefixes = true;
                intMsgStart += 3;
            }
            if ( intLevelLength > 0 ) {
            //Yes, its the debug level
                uint16DebugLevel = strMsg.midRef(0, intLevelLength).toUInt();
            //Offset to start of message
                strOutput = strMsg.mid(intMsgStart);
            }
            break;
        }
    }
    if ( uint16DebugLevel > clsDebugService::mscintDefaultLevel ) {
    //Do nothing debug level is higher than this messages level
        return;
    }
    if ( strOutput.isEmpty() == true ) {
    //Start off from start of message
        strOutput = strMsg;
    }
    if ( blnSuppressPrefixes == false ) {
    //Start with time stamp
        QTime tmNow(QTime::currentTime());
        bool blnVerbose = true;
        QString strPrefix(QString("S%1E%2T%3")
                        .arg(pService->int64GetNextSeqNo()
                            ,clsDebugService::mscintSeqNoLength
                            ,clsDebugService::mscintSeqNoBase, QChar('0'))
                        .arg(pService->int64GetElapsedTime()
                            ,clsDebugService::mscuintTimeLength
                            ,clsDebugService::mscintTimeBase, QChar('0'))
                        .arg(tmNow.toString(Qt::ISODateWithMs)));
        if ( pService->intGetDebugPrefixLength() == 0 ) {
            pService->setDebugPrefixLength(strPrefix.length());
        }
        switch( type ) {
        case QtCriticalMsg:
            strPrefix += "C";
            break;
        case QtDebugMsg:
            strPrefix += "D";
            break;
        case QtFatalMsg:
            strPrefix += "F";
            break;
        case QtInfoMsg:
            blnVerbose = false;
            break;
        case QtWarningMsg:
            strPrefix += "W";
            break;
        }        
        if ( blnVerbose == true ) {
            uint32_t uint32Line(0);
            long lngLine(0);
        //Remove any trailing whitespace
            QString strTemp("\n" + strPrefix);
            if ( pService->blnGetOriginDetails(strFile, strFunction, uint32Line) == true ) {
                lngLine = static_cast<long>(uint32Line);
            }
            if ( strFile.isEmpty() && context.file ) {
                strFile = QString(context.file);
            }
            if ( context.function ) {
                strFunction = QString(context.function);
                strFunction = strFunction.mid(0
                                        ,strFunction.indexOf(clsDebugService::msccBrktOpen));
            }
            if ( lngLine == 0 && context.line > 0 ) {
                lngLine = context.line;
            }
            if ( lngLine >= 0
              && !(slngLastLine == lngLine
                && sstrLastFile.compare(strFile) == 0
                && sstrLastFunction.compare(strFunction) == 0) ) {
                sstrLastFile = strFile;
                slngLastLine = lngLine;
                sstrLastFunction = strFunction;
                if ( blnVerbose == true && lngLine > 0 ) {
                    strTemp += QString("L%1").arg(lngLine
                                            ,clsDebugService::mscintLineNoLength
                                            ,clsDebugService::mscintLineNoBase, QChar('0'));
                }
                if ( blnVerbose == true && strFile.isEmpty() != true ) {
                    strTemp += QString("F%1").arg(strFile);
                }
                if ( blnVerbose == true && strFunction.isEmpty() != true ) {
                    strTemp += "[" + strFunction + "]\n";
                }
            }
    //Is a delimiter required?
            if ( !(strTemp.endsWith("\n") == true || strTemp.endsWith(":") == true) ) {
                strTemp += ":";
            }
    //Put it all together
            strOutput = strTemp + strOutput;
        }
    }
    //Split message into lines?
    QStringList slstParts(strOutput.split(scqcCarriageReturn));
    quint16 uint16Parts(slstParts.length());
    strOutput = "";
    for( quint16 uint16Part=0; uint16Part<uint16Parts; uint16Part++ ) {
        QString strPart(slstParts[uint16Part]);
        if ( strPart.isEmpty() == true ) {
            continue;
        }
        if ( slstParts.length() > 1 ) {
            if ( strPart.startsWith(scqcComma) ) {
                strPart = strPart.remove(scqcComma);
            }
            if ( uint16Part == 0 && strPart.startsWith(scqcOpenBracket) ) {
                strPart = clsDebugService::msccSpace + strPart.mid(1);
            }
            if ( uint16Part == uint16Parts && strPart.endsWith(scqcCloseBracket) ) {
                strPart = strPart.remove(scqcCloseBracket);
            }
        }
/*Is this used???        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 = qobject_cast<QtMsgType>(objJSON.take("type").toInt());
        } else */
        if ( strPart.compare(scqcCloseBracket) == 0 ) {
            continue;
        }
        if ( blnSuppressPrefixes == false && uint16Part > 0 ) {
            strOutput += scqcCarriageReturn;
        }
        strOutput += strPart;
    }
    if ( strOutput.isEmpty() != true ) {
#if defined(MODULE_BUILD)
        clsModHelper* pModHlpr(clsModHelper::psGetModHlprInstance());
        Q_ASSERT_X(pModHlpr!=nullptr, "clsDebugService::process"
                                    , "Cannot get module instance!");
        clsModule* pModule(pModHlpr->pGetModule());
        Q_ASSERT_X(pModule!=nullptr, "clsDebugService::process"
                                   , "No module set!");
        QJsonObject objJSON;
        clsJSON::addCommonJSONflds(objJSON, clsJSON::mscszCmdDebug);
        objJSON.insert(clsJSON::mscszText
                      ,QString("!%1!%2").arg(clsDebugService::strGetPrefix(), strOutput));
        emit pModule->sendJSON(objJSON, pModule->psckGetReceiver());
#else
        pService->blnPushDebug(strOutput);
#endif
    }
}

I'm having some strange output that I would appreciate help in tracking down what a possible cause is, here is a small part of the output to the file:

Client connecting...
Client connected
Client connecting...
!x1!Cli:mdXML:x1:ent connecting...
!x1!Cli:mdXML:x1:ent connected

The main application sends the first 3 lines, the message Client connecting... is sent from the main application to a module application as JSON using a socket:

void clsModule::onSendJSON(const QJsonObject& crobjJSON, QTcpSocket* psckReceiver) {
    if ( mblnReady != true ) {                
        sendLater(cstrGetAlias(), crobjJSON);
    } else if ( psckReceiver != nullptr && psckReceiver->isOpen() == true ) {
        QAbstractSocket::SocketState eState(psckReceiver->state());
        if ( eState == QAbstractSocket::ConnectedState ) {
    //Associate this TCP socket with the output data stream
            QByteArray arybytMsg(QJsonDocument(crobjJSON).toJson(QJsonDocument::Compact));
    //Write message
            psckReceiver->write(arybytMsg);
        }
    }
}

The message in the JSON is Client connecting... however, very reliably when the module receives it and its output from the service at the top of this post it gets split up with the module file name injected after Cli and before ent connecting....

I've search the source and there is only one place there the module alias is inserted into the JSON and its shown in the above at the bottom of the service.

[edit], should have included the service that writes to the file:

void clsDebugService::process() {
    QString strData;
    while ( true ) {
        QCoreApplication::processEvents();
    //Anything on the stack?
        clsDebugService::msMutex.lock();
        bool blnExit(clsDebugService::msblnExitWhenDebugStackEmpty)
            ,blnTerminating(mblnTerminating);
        int intSize =  mStack.size();
        clsDebugService::msMutex.unlock();
        if ( blnTerminating == true ) {
    //Terminate requested
            break;
        }
        if ( intSize == 0 ) {
            if ( blnExit == true ) {
    //Terminate module
                QCoreApplication::exit(0);
            }
    //Nothing on the stack, terminate thread
            break;
        }
        clsDebugService::msMutex.lock();
        strData = mStack.pop();
        clsDebugService::msMutex.unlock();
        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 ( strLine.isEmpty() == true ) {
                continue;
            }
            bool blnOpen, blnState;
            QString strFileName;
            clsDebugService::msMutex.lock();
            if ( blnToFile(blnOpen, blnState, strFileName) == true
              && blnState == true ) {
    //Is file open?
                if ( blnOpen == true ) {
                    QTextStream ts(&mFile);
                    ts << strLine.toLatin1().data() << "\r\n";

                    if ( ts.status() == QTextStream::WriteFailed ) {
    //Failed to send, put message back on stack
                        mStack.push_back(strData);
                        blnFileClose();
                    }
                }
            }
            if ( blnToConsole(blnState) == true && blnState == true ) {
    //Output to console
                std::cout << strLine.toLatin1().data() << "\n";
                std::cout << std::flush;
            }
            clsDebugService::msMutex.unlock();
        }
    }
    terminate();
    emit finished();
}

[SPlatten]

In the end after cleaning up the code and removing calls to processEvents the actual fault was caused by something quite simple in the string formatting logic.

[mchinand]

The two processes seem to be writing to the same file at the same time. I've never used it but Qt has QLockFile which you can use to prevent multiple processes from using a shared resource. Note though, the filename that is passed to the QLockFile constructor is a lock file, not the filename of the file that you want to prevent multiple processes from accessing at the same time.

[JonB]

@SPlatten
You can certainly use @mchinand's QLockFile, and that looks like the most "Qt" solution. I just don't like that it requires a separate file to lock.

Or you can do it as we (I) did before Qt. When one process wants to write its bytes to the file you use a C/C++ library call (like Linux lockf(), MSVC _locking()) on the file handle (QFile::handle()) to lock all bytes in the file (waits if other process has it locked), write bytes, release lock; other process does the same. Does the exclusivity "in-file", but at the expense of platform-dependent call.

[SPlatten]

This post is deleted!

[SPlatten]

This post is deleted!

[SPlatten]

Sorry people, I think I was misleading in my original post. Only the main application writes to the file the other applications send back the JSON via a socket to the main application and its this that writes to the file , so no file locking is required.

However there is still a problem with the output which I am investigating.

[JonB]

@SPlatten
If output is interleaved from within one application, are you sure you are not using multiple threads to write to the file...?

[J.Hilk]

@SPlatten your „void clsDebugService::process()“ is not reentrant save, but you call processevents in it, potentially allowing it de be excuted multiple times, jumping back and forth etc.

probably the issue of strange jumbled output.

[SPlatten]

@J-Hilk , thank you, I will take a look into this. To the process function I've added:

    static bool blnProcessingEvents(false);
    QString strData;
    while ( true ) {
        if ( blnProcessingEvents == false ) {
            blnProcessingEvents = true; //Prevent recursion
            QCoreApplication::processEvents();
            blnProcessingEvents = false;
        }

Just tested, results are still the same in the output file:

Client connected
!s1!Cli:mdSQL:s1:ent connecting...
!f1!Cli:mdFIO:f1:ent connecting...
!x1!Cli:mdXML:x1:ent connecting...
!s1!Cli:mdSQL:s1:ent connected
!f1!Cli:mdFIO:f1:ent connected
!x1!Cli:mdXML:x1:ent connected

Where the prefix !s1!, !f1! and !x1! are module alias, the message is supposed to read Client connecting... but it always has text inserted into it, which is very confusing.

[Christian Ehrlicher]

Do not call QCoreApplication::processEvents() inside the Qt message handler. It will just create problems (you can see the easiest by yourself).

[SPlatten]

@Christian-Ehrlicher , I've commented out the call to QCoreApplication::processEvents();, still getting the same problem.

[SPlatten]

In the end after cleaning up the code and removing calls to processEvents the actual fault was caused by something quite simple in the string formatting logic.

[J.Hilk]

@SPlatten
great you found the solution

nevertheless this

cleaning up the code and removing calls to processEvents

is never a bad thing to do :D