Cross thread signals (QueuedConnection). Miss SOME signals!

[progDes]

Hi all.

I have weired problem with signals sending between threads.

1) I have a thread. In the run() function I create a signals reciever object and connect signals to it:

void LogServiceThread::run()
{
    // Create worker.
    try
    {
        m_impl->m_worker.reset(new LogWorker(m_impl->m_fileName));
    }
    catch (...)
    {
        // Ignore all exceptions. If something gone wrong with worker - continue work silently.
    }
    // Connect signals to worker.
    if (!m_impl->m_worker.isNull())
    {
        connect(this, SIGNAL(writeAsynchSignal(QString)), m_impl->m_worker.data(), SLOT(writeMessage(QString)), Qt::QueuedConnection);
    }
    // Run event loop.
    exec();
}

void LogServiceThread::run()
{
    // Create worker.
    try
    {
        m_impl->m_worker.reset(new LogWorker(m_impl->m_fileName));
    }
    catch (...)
    {
        // Ignore all exceptions. If something gone wrong with worker - continue work silently.
    }
    // Connect signals to worker.
    if (!m_impl->m_worker.isNull())
    {
        connect(this, SIGNAL(writeAsynchSignal(QString)), m_impl->m_worker.data(), SLOT(writeMessage(QString)), Qt::QueuedConnection);
    }
    // Run event loop.
    exec();
}

To copy to clipboard, switch view to plain text mode 

2) Now I try to send som signals to it by main thread

void LogServiceThread::writeAsynch(const QString & string)
{
    emit writeAsynchSignal(string);
}

void LogServiceThread::writeAsynch(const QString & string)
{
    emit writeAsynchSignal(string);
}

To copy to clipboard, switch view to plain text mode 

So basically, this is an asynchronous thread safe logger. And I got weired problem: sometimes SOME log messages are missing. Some signals are emited but never come to slot! Sometimes I got all messages during run, some times only few.

What I am missing?

Thanks.

[high_flyer]

What happens if you change the signature of writeAsynch() to:

void writeAsynch(QString string)

void writeAsynch(QString string)

To copy to clipboard, switch view to plain text mode 

[MarekR22]

@up: this doesn't change anything.

@topic: not enough information! I have no idea what you should say more! First check debug logs, maybe Qt warns about some run time problems.
Secondly describe what you are trying to do? Maybe you can do it better way?

[progDes]

@topic: not enough information! I have no idea what you should say more! First check debug logs, maybe Qt warns about some run time problems.
Secondly describe what you are trying to do? Maybe you can do it better way?

Ok, basically this is simple thing.
I have a LogServiceThread object, which acts like a thread-safe object for logging. During the run() function I create a ThreadWorker object. It leaves in this thread and it responsible for actual writing of the log messages to the file. So, I service the log writing in separate thread. If other threads want to send something to log - they send a message to ThreadWorker using LogServiceThread::writeAsynch or (writeSynch if needed). writeAsynch returns immediately while message is added to the event queue of the log servicing thread. writeSynch is also executed in the same thread, but function is not returning until the message is really written to file (this is usefuly for example when logging qFatal, because after it the process is terminated).

Here is full implementation of these classes.

////////////////////////////////////////////////////////////////////////
/// LogServiceThreadImpl implementation.
////////////////////////////////////////////////////////////////////////
struct LogServiceThread::LogServiceThreadImpl
{
    QString m_fileName;
};
 
////////////////////////////////////////////////////////////////////////
/// LogServiceThread implementation.
////////////////////////////////////////////////////////////////////////
LogServiceThread::LogServiceThread(const QString & fileName, QObject * parent)
    : QThread(parent), m_impl(new LogServiceThreadImpl)
{
    m_impl->m_fileName = fileName;
}
 
LogServiceThread::~LogServiceThread()
{
 
}
 
void LogServiceThread::run()
{
    QScopedPointer<LogWorker> worker;
    // Create worker.
    try
    {
        worker.reset(new LogWorker(m_impl->m_fileName));
    }
    catch (...)
    {
        // Ignore all exceptions. If something gone wrong with worker - continue work silently.
        // We dont wont application to crash, cause of log.
    }
    // Connect signals to worker.
    if (!worker.isNull())
    {
        connect(this, SIGNAL(writeAsynchSignal(QString)), worker.data(), SLOT(writeMessage(QString)), Qt::QueuedConnection);
        connect(this, SIGNAL(writeSynchSignal(QString)), worker.data(), SLOT(writeMessage(QString)), Qt::BlockingQueuedConnection);
    }
    // Run event loop.
    exec();
}
 
void LogServiceThread::writeAsynch(const QString & string)
{
    emit writeAsynchSignal(string);
}
 
void LogServiceThread::writeSynch(const QString & string)
{
    emit writeSynchSignal(string);
}

////////////////////////////////////////////////////////////////////////
/// LogServiceThreadImpl implementation.
////////////////////////////////////////////////////////////////////////
struct LogServiceThread::LogServiceThreadImpl
{
    QString m_fileName;
};

////////////////////////////////////////////////////////////////////////
/// LogServiceThread implementation.
////////////////////////////////////////////////////////////////////////
LogServiceThread::LogServiceThread(const QString & fileName, QObject * parent)
    : QThread(parent), m_impl(new LogServiceThreadImpl)
{
    m_impl->m_fileName = fileName;
}

LogServiceThread::~LogServiceThread()
{
    
}

void LogServiceThread::run()
{
    QScopedPointer<LogWorker> worker;
    // Create worker.
    try
    {
        worker.reset(new LogWorker(m_impl->m_fileName));
    }
    catch (...)
    {
        // Ignore all exceptions. If something gone wrong with worker - continue work silently.
        // We dont wont application to crash, cause of log.
    }
    // Connect signals to worker.
    if (!worker.isNull())
    {
        connect(this, SIGNAL(writeAsynchSignal(QString)), worker.data(), SLOT(writeMessage(QString)), Qt::QueuedConnection);
        connect(this, SIGNAL(writeSynchSignal(QString)), worker.data(), SLOT(writeMessage(QString)), Qt::BlockingQueuedConnection);
    }
    // Run event loop.
    exec();
}

void LogServiceThread::writeAsynch(const QString & string)
{
    emit writeAsynchSignal(string);
}

void LogServiceThread::writeSynch(const QString & string)
{
    emit writeSynchSignal(string);
}

To copy to clipboard, switch view to plain text mode 

////////////////////////////////////////////////////////////////////////
/// LogWorkerImpl implementation
////////////////////////////////////////////////////////////////////////
struct LogWorker::LogWorkerImpl
{
    QScopedPointer<QFile> m_file;
    QScopedPointer<QTextStream> m_stream;
};
 
////////////////////////////////////////////////////////////////////////
/// LogWorker implementation
////////////////////////////////////////////////////////////////////////
LogWorker::LogWorker(const QString & fileName, QObject * parent)
    : QObject(parent), m_impl(new LogWorkerImpl)
{
    // Create file object (temporary for now)
    QScopedPointer<QFile> file(new QFile(fileName));
    if (file->open(QIODevice::WriteOnly | QIODevice::Text))
    {
        // Create text stream
        QScopedPointer<QTextStream> stream(new QTextStream(file.data()));
        // Now we succeeded:
        m_impl->m_file.reset(file.take());
        m_impl->m_stream.reset(stream.take());
    }
}
 
LogWorker::~LogWorker()
{
    // FIrst delete stream.
    m_impl->m_stream.reset(0);
    // Than file.
    m_impl->m_file.reset(0);
}
 
void LogWorker::writeMessage(QString s)
{
    (*m_impl->m_stream.data()) << s << endl;
    m_impl->m_file->flush();
}

////////////////////////////////////////////////////////////////////////
/// LogWorkerImpl implementation
////////////////////////////////////////////////////////////////////////
struct LogWorker::LogWorkerImpl
{
    QScopedPointer<QFile> m_file;
    QScopedPointer<QTextStream> m_stream;
};

////////////////////////////////////////////////////////////////////////
/// LogWorker implementation
////////////////////////////////////////////////////////////////////////
LogWorker::LogWorker(const QString & fileName, QObject * parent)
    : QObject(parent), m_impl(new LogWorkerImpl)
{
    // Create file object (temporary for now)
    QScopedPointer<QFile> file(new QFile(fileName));
    if (file->open(QIODevice::WriteOnly | QIODevice::Text))
    {
        // Create text stream
        QScopedPointer<QTextStream> stream(new QTextStream(file.data()));
        // Now we succeeded:
        m_impl->m_file.reset(file.take());
        m_impl->m_stream.reset(stream.take());
    }
}

LogWorker::~LogWorker()
{
    // FIrst delete stream.
    m_impl->m_stream.reset(0);
    // Than file.
    m_impl->m_file.reset(0);
}

void LogWorker::writeMessage(QString s)
{
    (*m_impl->m_stream.data()) << s << endl;
    m_impl->m_file->flush();
}

To copy to clipboard, switch view to plain text mode 

So this is quite simple.

The Qt doesn't send any debug messages. Btw, all qt messages are redirected to that log. You could say that I miss some qt messages during construction of the LogServiceThread. But no: 1) I checked that. 2) I firstly create LogServiceThread and only than install message handler (so before this - qt messages are sent to standard output, and there is nothing there).

---

Added after 15 minutes:

Ok, I have found a reason. Although this seems strange to me anyway.
If I put some long dummy operation (2 seconds to perform) after LogServiceThread construction and before first log message sent - I get it working.
Something like this: for (int i = 0; i < 100000000; i++) cos(0.54f);
This brings me to the point: if I send message before the QThread::exec() is called (event loop is runned) - the signals are missing! Ok, although this seems not good - it can be expected.
But there is something I could considered as a bug of Qt. If the above scenario occurs - the messages that are sent after the starting of even loop also CAN miss! Because I have few messages written on application close, and I still miss them. I close application after few seconds of running it - so there is a guarantee that exec() already called.

So, although this looks like a Qt bug for me, I will add a synchronization point to ensure that no signals emitted until exec() is called. This should work.

---

Added after 9 minutes:

Another question.
How can I know that event loop was already created and I can send signals? I could set some flag just before calling exec(), but this is also not safe, cause who knows what is inside exec() and when I really can already send signals?

---

Added after 11 minutes:

Wow, I'm so silly!
Nothing about Qt event queue or something.

1) The messages on startup are missing because they are sent before LogWorker is created!
2) The messages on shutdown are missing because quit() event comes out of order (which is ok, this is another problem to think on).

Resolved!

[high_flyer]

@up: this doesn't change anything.

The idea was that since its a reference, the referenced object might have changed to be a null string before the thread came to process the slot.

[progDes]

The idea was that since its a reference, the referenced object might have changed to be a null string before the thread came to process the slot.

No. Look at the signal and slot definition, the string is passed by value.

[MarekR22]

The idea was that since its a reference, the referenced object might have changed to be a null string before the thread came to process the slot.

Read qt documentation about passing signal to slots. Const reference and value doesn't have any differences, copy is always made (in case of QString shallow copy).

@topic:
if you mixed calls of LogServiceThread::writeAsynch and LogServiceThread::writeSynch even in single thread then you did a big mistake.
In one case you enforced call of LogWorker::writeMessage from LogServiceThread in another case it happens from custom (probably mian) thread.
But you method LogWorker::writeMessage is not thread safe, so you are corrupting data in stream in unpredictable way.
Use only writeAsynch method this will be thread safe!

In general qt delivers a loger. Just include QDebug header file and use it:

qDebug() << "Messege" << value << value;

qDebug() << "Messege" << value << value;

To copy to clipboard, switch view to plain text mode 

It is possible to store qDebug in a file, I have to find it in documentation (it is possible that invoking application with "-o filename" option is enough I'm not sure)