qDebug() messages aren't flushing

[davethomaspilot]

I have a simple program that starts a single shot timer. When the timer expires, a Qprocess is started that attempts to establish a bluetooth connection.

If the connection fails, the timer is restarted. This continues until the connection is successful.

The program that does the bluetooth connection (bluetoothctl) consumes the entire processor (rpi zero W) until it finishes. I see this when I have a second ssh session open while my program is running. Bluetoothctl runs several seconds while attempting to make a connection. During this time, the second ssh session is non-responsive.

This is ok--I don't have a GUI that needs refreshing. But, I do want to make sure there's nothing wrong in my code (like unintentional recursion) that causing the cpu resource to be consumed. So, I have some qDebug() statements to help with that.

Initially, the qDebug statements print when expected. Then, as the program continues to try to make a connection, there is an ever increasing delay before the qDebug output is seen. Eventually, I see no qDebug output at all, but when I turn on the client bluetooth so that a successful connection can be made, the connection is successful and all the delayed qDebug statements appear.

I have added fflush(stderr), fflush(stdout), and QCoreApplication.processEvents() after the qDebug statements, but they are still delayed.

So, while the application is "working", I worry that eventually, whatever queue is saving the messages will get full, or worse, there's really some mistake in my code that's causing this strange bevhaviour.

Why are the qDebug statements delayed? Can anything be done to get them to print immediately after the QProcess finishes?

Here's the code that runs when the timer expires:


void Bluetooth::connectDev(void)
{
if (!isConnected())
{
emit disconnected();
qDebug() << "attempting connection";

// If we've connected previously, we can use the info in settings.
if (controllerMac != "none" && deviceMac != "none")
{

QProcess echoP;
QProcess btP;
QString btCmd = "select " + controllerMac + "\\nconnect " + deviceMac + "\\nquit\\n";
echoP.setStandardOutputProcess(&btP);

echoP.start("echo -e """"" + btCmd + """");
qDebug() << "starting bluetoothctl";
btP.start("bluetoothctl");
btP.setProcessChannelMode(QProcess::ForwardedChann els);
if (!echoP.waitForStarted())
{
qDebug("echoP never started");
return;
}
else
qDebug("echoP started");

if (!btP.waitForStarted())
{
qDebug("btP not started");
autoConnectTimer->start();
return;
}
else
qDebug("btP started");

echoP.waitForFinished();
btP.waitForFinished();
qDebug()<< "bluetoothctl finished, connect attempts = " << connectionAttempts++;
QByteArray output = btP.readAllStandardOutput();
qDebug()<< output;
fflush(stdout);
fflush(stderr);
qDebug() << "restarting autoconnect timer";
fflush(stderr);
}
}
else
{
connectionAttempts = 0;
setDiscoverable(false);
emit connected();
qDebug() << "already connected";
}
QCoreApplication::processEvents();
autoConnectTimer->start();
}

Thanks for any help!

Added after 1 29 minutes:

I've been playing around with timer interval. Slowing it down until the qDebug messages don't get delay.

It's strange--it takes at most 2-3 seconds for the QProcess to finish, based on qDebug output after waitForFinished(). Yet, if I poll more often than about eight seconds, the debug output gets more and more delayed until there's none.

It's as if there's significant cpu resource being consumed AFTER the waitForFinished() unblocks. As much (maybe more) after the waitForFinished than during the actual process execution.