Unsolved Preventing a method being called multiple times?
-
I have the following question:
For writing a log file, I have the basically the following slot function in a custom log file class:
void Log::addToLog(QString logstring) { QWriteLocker locker(lock); if(!logfile.open(QIODevice::Append | QIODevice::Text)) { // Write to log file emit error("Log couldn't be opened"); return; } else { QString output_string; output_string = QDateTime::currentDateTime().\ toString("yyyy-MM-dd hh:mm:ss.zzz") \ + " - " + logstring + "\r\n"; QTextStream logStream(&logfile); logStream << output_string; logfile.close(); } }
With "logfile" being a QFile object.
My app contains several QThreads. These threads now emit signals with the desired log string as parameter. The main thread now has the only instance of the Log class and connects the signals to the the log's write slot (addToLog). This works nicely when sending signals from different threads (due to the locker) the block until the write slot is free. However, when emitting the signal from the same thread another time while the addToLog function is still processed, it is simply called again and the slot function is executed several times at the same time, bringing unpredictable order of the strings being written to the file.
So my question is: Is there some way to prevent the slot function being called a second time without using a wait loop (which causes a deadlock)?
Or, am I safe to assume that the actual writing to the file can't cause any problems when the function is executed several times at the same time?
Or maybe anybody has some other idea for me (actually my goal is simply to have a log file which can be written from different threads)?
Kind regards,
Markus
-
@MarkusBraitner How is it possible that other signals from same thread are handled while addToLog is still executing? Usually signals are handled one after the other. How can other signals be emitted in the same thread while it is inside addToLog?
-
This post is deleted! -
This post is deleted! -
Hm, maybe it's only that I'm drawing the wrong conclusion. Or maybe I'm thinking about this thing already for too long so that I don't see the obvious any more... Maybe somebody find the problem (in the code or my conclusions):
For debugging, my slot function looks as follows:
void MTLog::addToLog(QString logstring) { qDebug() << QDateTime::currentDateTime().\ toString("yyyy-MM-dd hh:mm:ss.zzz") \ << " - Entering function:" << logstring; QWriteLocker locker(lock); /* If log file is currently already used by same thread, return * immediately. */ if(busy) { qDebug() << QDateTime::currentDateTime().\ toString("yyyy-MM-dd hh:mm:ss.zzz") \ << " - Log busy - request rejected: " << logstring; return; } busy = true; qDebug() << QDateTime::currentDateTime().\ toString("yyyy-MM-dd hh:mm:ss.zzz") \ << " - After locker: " << logstring; if(!logfile.open(QIODevice::Append | QIODevice::Text)) { // Write to log file qDebug() << "Log couldn't be opened"; emit error("Log couldn't be opened"); return; } else { qDebug() << QDateTime::currentDateTime().\ toString("yyyy-MM-dd hh:mm:ss.zzz") \ << " - About to write to file" << logstring; QString output_string; output_string = QDateTime::currentDateTime().\ toString("yyyy-MM-dd hh:mm:ss.zzz") \ + " - " + logstring + "\r\n"; QTextStream logStream(&logfile); logStream << output_string; logfile.close(); QTest::qWait(2000); qDebug() << QDateTime::currentDateTime().\ toString("yyyy-MM-dd hh:mm:ss.zzz") \ << " - Finished writing" << logstring; } qDebug() << QDateTime::currentDateTime().\ toString("yyyy-MM-dd hh:mm:ss.zzz") \ << " - Leaving function" << logstring; busy = false; }
For testing, I set up a unit test as follows (again, uneccesary lines deleted):
void TestLogTest::threadAddToLog_signal_timed() { TestWrite3 test1; QThread t_test1; test1.moveToThread(&t_test1); t_test1.start(); connect(&test1, &TestWrite3::sig_addToLog, logfile, &MTLog::addToLog, Qt::QueuedConnection); QTime triggertime; triggertime = QTime::currentTime().addSecs(2); test1.addToLog("Signal: Message from thread1", triggertime); QTest::qWait(10000); t_test1.quit(); t_test1.wait(); }
with the TestWrite3 class being defined as
class TestWrite3 : public QObject { Q_OBJECT public: TestWrite3(); public slots: void writeToLog(); void addToLog(QString, QTime); private: QTimer timer1; QTimer timer2; QString logtext; signals: void sig_addToLog(QString); };
and the corresponding functions as
TestWrite3::TestWrite3() { timer1.setSingleShot(true); timer2.setSingleShot(true); }
void TestWrite3::addToLog(QString logstring, QTime time) { logtext = logstring; connect(&timer1, &QTimer::timeout, this, &TestWrite3::writeToLog, Qt::QueuedConnection); connect(&timer2, &QTimer::timeout, this, &TestWrite3::writeToLog, Qt::QueuedConnection); timer1.start(time.msecsSinceStartOfDay() - \ QTime::currentTime().msecsSinceStartOfDay()); timer2.start(time.msecsSinceStartOfDay() - \ QTime::currentTime().msecsSinceStartOfDay() + 1000); }
void TestWrite3::writeToLog() { qDebug() << QDateTime::currentDateTime().\ toString("yyyy-MM-dd hh:mm:ss.zzz") \ << " - signal sig_addToLog(" << logtext << ")"; emit sig_addToLog(logtext); }
What it does is basically:
The test function moves the test class TestWrite3 to an own thread and calls its addToLog function with a triggertime (2s ahead the current time) as parameter. This function now sets up two timers, one for trigger time, the other for trigger time + 1s. When the timers are elapsed, a slot function in TestWrite3 is called, emitting the signal for writing the log file entry. The log write method has a delay of 2s, so the second sig_addToLog signal gets emitted while the first write is still taking place.What I get is the following debug output:
"2017-11-21 14:37:49.748" - signal sig_addToLog( "Signal: Message from thread1" )
"2017-11-21 14:37:49.749" - Entering function: "Signal: Message from thread1"
"2017-11-21 14:37:49.750" - After locker: "Signal: Message from thread1"
"2017-11-21 14:37:49.751" - About to write to file "Signal: Message from thread1"
"2017-11-21 14:37:50.745" - signal sig_addToLog( "Signal: Message from thread1" )
"2017-11-21 14:37:50.746" - Entering function: "Signal: Message from thread1"
"2017-11-21 14:37:50.747" - MTLog busy - request rejected: "Signal: Message from thread1"
"2017-11-21 14:37:51.760" - Finished writing "Signal: Message from thread1"
"2017-11-21 14:37:51.761" - Leaving function "Signal: Message from thread1"So, for me it seems the function is called a second time while it is still being executed. Anybody an idea?
Kind regards,
Markus
PS: Since I made many more tests, I had to extract the relevant lines of code (for better readability) - hopefully I've included all necessary lines...
-
By the way, how to make all parts of the code getting rendered as such? Is there some formatting code that I can use?
-
@MarkusBraitner Enclose your code in three apostrophes
-
@jsulm Thank you!