QxtLogger logging out of order

[Isaac Gartner]

Hi Qxt devs,

I just started using QxtLogger, using libqxt 0.6.2, Qxt 4.8.2, on Windows 7.

I'm using it to debug a multithreaded application. It seems that log statements are not being written to the log in the order they are being sent to the logger. In other words, when I step through the code in the debugger, the order I see the logger being called with various log statements, but in the resulting log file, those log statements are written in a different order.

I suspect this has something to do with the fact that the logger is being called from various threads, but I thought QxtLogger was written to accomodate multithreading.

I'm wondering if this is a known bug and if there is a fix?

I've attached a sample log.

You'll notice there is a section that repeats as follows:

[14:14:32.951] [Debug] HtClient::interrruptWrite : responseMutex locked [14:14:32.955] [Debug] HtClient::interrruptWrite : waitForResponse received [14:14:32.955] [Debug] HtClient::interruptRead : responseMutex locked [14:14:32.959] [Debug] HtClient::interruptRead : waitForResponse received <repeat>

then a section that repeats as follows:

[14:14:33.528] [Debug] HtServer::interruptWrite [14:14:33.528] [Debug] HtUsb::InterruptWrite [14:14:33.528] [Debug] HtClient::onWriteResponse [14:14:33.528] [Debug] HtServer::interruptRead [14:14:33.528] [Debug] HtUsb::InterruptRead [14:14:33.528] [Debug] HtClient::onReadResponse <repeat>

When I step through the code, those log statements are being interleaved, so the log should look like the following (aside from the time stamps):

[14:14:32.951] [Debug] HtClient::interrruptWrite : responseMutex locked [14:14:33.528] [Debug] HtServer::interruptWrite [14:14:33.528] [Debug] HtUsb::InterruptWrite [14:14:33.528] [Debug] HtClient::onWriteResponse [14:14:32.955] [Debug] HtClient::interrruptWrite : waitForResponse received

[Lawrence (Dee) Holtsclaw]

Cross-thread signal/slot connections must pass through Qt's event queue. Although I would expect requests made in other threads to be processed in order, any originating from the same thread as the logger would most likely be handled immediately. Are you using connect() or calling the methods directly?

Disclaimer: I didn't write that code nor am I familiar with it's operation so I could be completely wrong.

[Isaac Gartner]

(Reply via [e-mail]):

Hi Lawrence,

Thanks for the quick response!

I'm calling the logger directly, using, e.g.,: qxtLog->debug( "message" );

Your explanation sounds reasonable. I'll try creating the logger in a separate thread and see what happens...

-Isaac

On Wed, Aug 15, 2012 at 2:51 PM, Lawrence Holtsclaw < [e-mail]> wrote:

[Isaac Gartner]

(Reply via [e-mail]):

Seems like it might be a bit difficult to move QxtLogger into a separate thread. The object receiving the log messages is the private object, which I'm guessing is not accessible to me. Any suggestions on how to move the private object to my new thread?

Thanks, Isaac

On Wed, Aug 15, 2012 at 2:51 PM, Lawrence Holtsclaw < [e-mail]> wrote:

[Isaac Gartner]

(Reply via [e-mail]):

Problem solved. I just needed to make sure the logger instance was created from within my new thread. Now my log statements appear in the correct order in the log file.

On Wed, Aug 15, 2012 at 2:51 PM, Lawrence Holtsclaw < [e-mail]> wrote: