Improved script.wait (#794)

New script.wait tries hard to be as precise as desired without meaningful deviation on different platform (TRIK, macOS, Windows, GNU/Linux desktops and servers)
Also some improvements for responsiveness
* Fix event handling: DO NOT USE EVENT-LOOPS in run/runDirect

tests/common.pri

@@ -37,6 +37,9 @@ OTHER_FILES += \
 	$$PWD/test-system-config.xml \
 	$$PWD/test-model-config.xml \
 
+implementationIncludes(tests/testUtils)
+links(testUtils)
+
 trik_new_age {
     copyToDestdir($$PWD/kernel-4.14/test-system-config.xml, now)
     copyToDestdir($$PWD/kernel-4.14/test-model-config.xml, now)

tests/mainTest.cpp

@@ -17,17 +17,20 @@
 #include <QtCore/qglobal.h>
 #include <QtCore/QCoreApplication>
 
-
 #include <trikKernel/coreDumping.h>
 #include <trikKernel/loggingHelper.h>
 
+#include <testUtils/eventFilter.h>
+
 int main(int argc, char *argv[])
 {
 	::testing::InitGoogleTest(&argc, argv);
 
 	QCoreApplication app(argc, argv);
 
-	Q_UNUSED(app);
+	tests::utils::EventFilter eventFilter;
+	// useful to debug events
+	// app.installEventFilter(&eventFilter);
 
 	trikKernel::LoggingHelper loggingHelper(".", QsLogging::Level::WarnLevel);
 	Q_UNUSED(loggingHelper);

tests/testUtils/include/testUtils/eventFilter.h

@@ -0,0 +1,34 @@
+/* Copyright 2024, Iakov Kirilenko
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License. */
+#pragma once
+#include <QObject>
+#include "testUtilsDeclSpec.h"
+
+namespace tests {
+namespace utils {
+
+/// Event filter for debug purposes
+class TESTUTILS_EXPORT EventFilter: public QObject
+{
+	Q_OBJECT
+public:
+	/// ctor
+	explicit EventFilter(QObject *parent = nullptr):QObject(parent) {}
+
+	/// default method to filter events
+	bool eventFilter(QObject *o, QEvent *e) override;
+};
+
+}
+}

tests/testUtils/src/eventFilter.cpp

@@ -0,0 +1,35 @@
+/* Copyright 2024, Iakov Kirilenko
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License. */
+
+#include "eventFilter.h"
+#include <QDebug>
+#include <QtCore/private/qobject_p.h>
+#include <QMetaMethod>
+
+bool tests::utils::EventFilter::eventFilter(QObject *o, QEvent *e) {
+	QMessageLogger log;
+	auto print = log.debug();
+	print << o << e;
+	switch(e->type()) {
+	default:break;
+	case QEvent::Type::MetaCall:
+		QMetaCallEvent * mev = static_cast<QMetaCallEvent*>(e);
+		QMetaMethod slot = o->metaObject()->method(mev->id());
+		print << slot.methodSignature() << slot.methodType() << slot.name() << slot.typeName();
+		break;
+	}
+
+
+	return false;
+}

tests/testUtils/testUtils.pro

@@ -18,7 +18,7 @@ TEMPLATE = lib
 
 DEFINES += TESTUTILS_LIBRARY
 
-QT += network
+QT += network core-private
 
 interfaceIncludes(trikNetwork)
 links(trikNetwork)
@@ -27,7 +27,9 @@ HEADERS += \
 	$$PWD/include/testUtils/tcpClientSimulator.h \
 	$$PWD/include/testUtils/wait.h \
 	$$PWD/include/testUtils/testUtilsDeclSpec.h \
+	$$PWD/include/testUtils/eventFilter.h
 
 SOURCES += \
 	$$PWD/src/tcpClientSimulator.cpp \
 	$$PWD/src/wait.cpp \
+	$$PWD/src/eventFilter.cpp \	

tests/trikPyRunnerTests/trikPyRunnerTest.cpp

@@ -59,13 +59,13 @@ int TrikPyRunnerTest::run(const QString &script)
 		if (!e.isEmpty()) {
 			rc = EXIT_SCRIPT_ERROR;
 			std::cerr << qPrintable(e) << std::endl;
-		}
-		QCoreApplication::processEvents(); // for stdout messages
+		}		
 		l.exit(rc);
 	}, Qt::QueuedConnection ) ; // prevent `exit` before `exec` via QueuedConnection
 	mStdOut.clear();
 	mScriptRunner->run(script, "_.py");
 	auto code = l.exec();
+	QCoreApplication::processEvents(); // for stdout messages
 	std::cout << qPrintable(mStdOut) << std::endl;
 	return code;
 }
@@ -74,14 +74,14 @@ int TrikPyRunnerTest::runDirectCommandAndWaitForQuit(const QString &script)
 {
 	QEventLoop l;
 	QObject::connect(&*mScriptRunner, &trikScriptRunner::TrikScriptRunnerInterface::completed
-					 , &l, [&l](const QString &e) {
-			QCoreApplication::processEvents(); // dispatch events for print/stdout
+					 , &l, [&l](const QString &e) {			
 			l.exit(e.isEmpty() ? EXIT_SCRIPT_SUCCESS
 									   : (qDebug() << e, EXIT_SCRIPT_ERROR));
 	}, Qt::QueuedConnection ) ; // prevent `exit` before `exec` via QueuedConnection
 	mStdOut.clear();
 	mScriptRunner->runDirectCommand(script);
 	auto code = l.exec();
+	QCoreApplication::processEvents(); // dispatch events for print/stdout
 	std::cout << mStdOut.toStdString() << std::endl;
 	return code;
 }
@@ -160,7 +160,7 @@ TEST_F(TrikPyRunnerTest, scriptWait)
 	ASSERT_EQ(err, EXIT_SCRIPT_SUCCESS);
 	err = runDirectCommandAndWaitForQuit("print('Elapsed %d ms with expected %d ms' % (elapsed, timeout));");
 	ASSERT_EQ(err, EXIT_SCRIPT_SUCCESS);
-	err = runDirectCommandAndWaitForQuit("#assert(abs(elapsed-timeout) < 5)");
+	err = runDirectCommandAndWaitForQuit("pass #assert(abs(elapsed-timeout) < 5)");
 	ASSERT_EQ(err, EXIT_SCRIPT_SUCCESS);
 }
 

trikScriptRunner/src/pythonEngineWorker.cpp

@@ -370,6 +370,7 @@ void PythonEngineWorker::doRun(const QString &script, const QFileInfo &scriptFil
 	mBrick->keys()->reset();
 	mState = running;
 	auto ok = recreateContext();
+	QCoreApplication::processEvents();
 	if (!ok) {
 		emit completed(mErrorMessage,0);
 		return;
@@ -386,8 +387,10 @@ void PythonEngineWorker::doRun(const QString &script, const QFileInfo &scriptFil
 
 	auto wasError = mState != ready && PythonQt::self()->hadError();
 	mState = ready;
+	QCoreApplication::processEvents(); //dispatch events before reset
 	mScriptExecutionControl->reset();
 	releaseContext();
+	QCoreApplication::processEvents(); //dispatch events before emitting the signal
 	if (wasError) {
 		emit completed(mErrorMessage, 0);
 	} else {
@@ -410,6 +413,7 @@ void PythonEngineWorker::doRunDirect(const QString &command)
 		recreateContext();
 	}
 	mMainContext.evalScript(command);
+	QCoreApplication::processEvents();
 	auto wasError = PythonQt::self()->hadError();
 	if (wasError) {
 		emit completed(mErrorMessage, 0);

trikScriptRunner/src/scriptEngineWorker.cpp

@@ -25,6 +25,7 @@
 #include "scriptable.h"
 #include "utils.h"
 
+#include <QCoreApplication>
 #include <QFileInfo>
 #include <QsLog.h>
 
@@ -220,6 +221,7 @@ void ScriptEngineWorker::doRun(const QString &script)
 	mThreading.waitForAll();
 	const QString error = mThreading.errorMessage();
 	QLOG_INFO() << "ScriptEngineWorker: evaluation ended with message" << error;
+	QCoreApplication::processEvents();
 	emit completed(error, mScriptId);
 }
 
@@ -254,6 +256,7 @@ void ScriptEngineWorker::doRunDirect(const QString &command, int scriptId)
 			msg = mDirectScriptsEngine->uncaughtException().toString();
 			mDirectScriptsEngine.reset();
 		}
+		QCoreApplication::processEvents();
 		Q_EMIT completed(msg, mScriptId);
 	}
 }

trikScriptRunner/src/scriptExecutionControl.cpp

@@ -20,7 +20,10 @@
 #include <QtCore/QFileInfo>
 #include <QtCore/QStringList>
 
+#include <QElapsedTimer>
+#include <QOperatingSystemVersion>
 #include <QRandomGenerator>
+#include <QThread>
 #include <QsLog.h>
 
 #include <trikControl/utilities.h>
@@ -56,14 +59,74 @@ QObject* ScriptExecutionControl::timer(int milliseconds)
 	return result;
 }
 
-void ScriptExecutionControl::wait(const int &milliseconds)
-{
+static inline int waitWithTimerType(ScriptExecutionControl *sec, int ms, Qt::TimerType tt) {
 	QEventLoop loop;
-	QObject::connect(this, &ScriptExecutionControl::stopWaiting, &loop, &QEventLoop::quit);
+	QObject::connect(sec, &ScriptExecutionControl::stopWaiting, &loop, std::bind(&QEventLoop::exit, &loop,  -1));
 	QTimer t;
-	connect(&t, &QTimer::timeout, &loop, &QEventLoop::quit);
-	t.start(milliseconds);
-	loop.exec();
+	t.setTimerType(tt);
+	QObject::connect(&t, &QTimer::timeout, &loop, &QEventLoop::quit);
+	t.start(ms);
+	return loop.exec();
+}
+
+void ScriptExecutionControl::wait(const int &milliseconds)
+{
+	QElapsedTimer elapsed;
+	elapsed.start();
+	auto precision = 0;
+
+	// Try to send all posted events even if timer in ms is very short
+	QCoreApplication::sendPostedEvents();
+	auto diff = milliseconds - elapsed.elapsed();
+	if (diff <= precision) {
+		return;
+	}
+#if 0 // looks useless because QEventLoop.exec with PreciseTimer can do the same
+	QCoreApplication::processEvents();
+	diff = milliseconds - elapsed.elapsed();
+	if (diff <= precision) {
+		return;
+	}
+
+	for(QEventLoop l;l.processEvents();) {
+		diff = milliseconds - elapsed.elapsed();
+		if (diff <= precision) {
+			return;
+		}
+	}
+#endif
+	constexpr auto preciseTimerDelta = 20;
+
+	if (diff > 100
+			&& waitWithTimerType(this, std::max(diff - preciseTimerDelta, 0ll), Qt::TimerType::CoarseTimer)) {
+		return;
+	}
+	diff = milliseconds - elapsed.elapsed();
+
+	// QThread::usleep does not work for Windows, sleeps too long, about 20 ms
+	constexpr auto usleepDelta = QOperatingSystemVersion::currentType() != QOperatingSystemVersion::Windows ? 3 : 0;
+	constexpr auto spinLockDelta = QOperatingSystemVersion::currentType() != QOperatingSystemVersion::Windows ? 2 : 3;
+
+	static_assert(preciseTimerDelta > usleepDelta, "Use timer for longer sleep");
+
+	if (waitWithTimerType(this, std::max(0ll, diff - (usleepDelta+spinLockDelta)), Qt::TimerType::PreciseTimer)) {
+			return;
+	}
+
+	diff = milliseconds - elapsed.elapsed();
+	if (diff <= precision) {
+		// This is enough
+		return;
+	}
+
+
+	if (diff > usleepDelta && usleepDelta > spinLockDelta) {
+		QThread::usleep( (diff - spinLockDelta) * 1000);
+	}
+	// Ok, spin-lock to wait for a few milliseconds
+	while ((milliseconds - elapsed.elapsed()) > precision ) {
+		/* do nothing */
+	}
 }
 
 qint64 ScriptExecutionControl::time() const

trikScriptRunner/src/trikJavaScriptRunner.cpp

@@ -63,6 +63,11 @@ TrikJavaScriptRunner::~TrikJavaScriptRunner()
 	// We need an event loop to process pending calls from dying thread to the current
 	// mWorkerThread.wait(); // <-- !!! blocks pending calls
 	wait.exec();
+	// The thread has finished, events have been processed above
+	constexpr auto POLITE_TIMEOUT = 100;
+	if (!mWorkerThread.wait(POLITE_TIMEOUT)) {
+		QLOG_FATAL() << "JS thread failed to exit gracefully in" << POLITE_TIMEOUT << "ms";
+	}
 }
 
 void TrikJavaScriptRunner::registerUserFunction(const QString &name, QScriptEngine::FunctionSignature function)

trikScriptRunner/src/trikPythonRunner.cpp

@@ -54,6 +54,19 @@ TrikPythonRunner::~TrikPythonRunner()
 	// We need an event loop to process pending calls from dying thread to the current
 	// mWorkerThread.wait(); // <-- !!! blocks pending calls
 	wait.exec();
+	// The thread has finished, events have been processed above
+	constexpr auto POLITE_TIMEOUT = 100;
+	if (!mWorkerThread->wait(POLITE_TIMEOUT)) {
+		QLOG_WARN() << "Python thread failed to exit gracefully in" << POLITE_TIMEOUT
+					 << "ms, re-trying with 3x timeout";
+		if (!mWorkerThread->wait(3*POLITE_TIMEOUT)) {
+			QLOG_ERROR() << "Python thread failed to exit gracefully in 3x timeout,"
+						 << " next attempt is unlimited timeout and may hang";
+			mWorkerThread->wait();
+		} else {
+			QLOG_INFO() << "Python thread succeeded to shutdown with 3x timeout";
+		}
+	}
 }
 
 void TrikPythonRunner::run(const QString &script, const QString &fileName)

trikScriptRunner/src/trikScriptRunner.cpp

@@ -20,6 +20,7 @@
 
 #include <trikKernel/timeVal.h>
 #include "threading.h"
+#include <QCoreApplication>
 #include <QMetaMethod>
 
 using namespace trikControl;