Diagnosing problem.
-
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 connectedThe 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
You can certainly use @mchinand'sQLockFile, 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. -
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.
-
@SPlatten
You can certainly use @mchinand'sQLockFile, 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. -
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.
-
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.
-
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 connectedThe 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 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.
Be aware of the Qt Code of Conduct, when posting : https://forum.qt.io/topic/113070/qt-code-of-conduct
Q: What's that?
A: It's blue light.
Q: What does it do?
A: It turns blue. -
@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.
@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 connectedWhere 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.
-
Do not call QCoreApplication::processEvents() inside the Qt message handler. It will just create problems (you can see the easiest by yourself).
Qt Online Installer direct download: https://download.qt.io/official_releases/online_installers/
Visit the Qt Academy at https://academy.qt.io/catalog -
Do not call QCoreApplication::processEvents() inside the Qt message handler. It will just create problems (you can see the easiest by yourself).
-
@Christian-Ehrlicher , I've commented out the call to QCoreApplication::processEvents();, still getting the same problem.
-
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.
