Obtain script backtrace when a log event is generated in C++ code #1156

daleglass · 2021-04-04T22:08:34Z

This is a very, very early prototype and doesn't work. Here's the overall idea:

When a C++ function logs something, such as:

[04/04 23:16:38] [WARNING] [hifi.scriptengine] Script.include() ignoring file path -- outside of standard libraries:  "" "/home/dale/git/vircadia/build-logging/interface/scripts"

We want to figure out where that came from. Which script resulted in this function being called? And this works to some extent:

Script context:
	:-1 include
	file:///home/dale/git/vircadia/build-logging/interface/scripts/defaultScripts.js:153 runDefaultsTogether
	file:///home/dale/git/vircadia/build-logging/interface/scripts/defaultScripts.js:185 
[04/04 23:16:38] [WARNING] [hifi.scriptengine] Script.include() ignoring file path -- outside of standard libraries:  "" "/home/dale/git/vircadia/build-logging/interface/scripts"

The problem is that a problem can be found at any arbitrary depth, not just in whatever QScriptEngine calls directly. So I figured out a way around that. Qt has the QScriptEngineAgent, which allows us invoke code at interesting points, such as script function calls, including calls to native code.

So the idea is:

On every native function call from ScriptEngine, ScriptEngineLoggingAgent::functionEntry is called.
We generate a backtrace.
We give this to ScriptContextHelper, which remembers backtraces per-thread.
Execution continues, native function runs
Possibly more native code runs
Code logs an event. Execution eventually ends up in LogHandler.
LogHandler checks ScriptContextHelper, prints the backtrace if there's any.
Eventually the native code finishes running
ScriptEngineLoggingAgent::functionExit is called
ScriptContextHelper wipes the current backtrace.

Unfortunately it doesn't quite work. Problems:

There's probably something thread-related horribly wrong somewhere
functionEntry seems to be called multiple times per event, hence the stack
Trying to generate a backtrace sometimes results in functionEntry calling itself through the Qt code.
I tried constructing a backtrace by hand, hoping that avoiding examining objects and arguments and just printing names would be safe, but it doesn't seem to help.

#15 0x00007ffff51720a6 in ScriptEngineLoggingAgent::functionEntry(long long) (this=0x16e8a1a0, scriptId=-1) at /home/dale/git/vircadia/vircadia-master/libraries/script-engine/src/ScriptEngineLoggingAgent.cpp:37
#16 0x00007ffff017e81c in QTJSC::NativeFuncWrapper::operator()(QTJSC::ExecState*, QTJSC::JSObject*, QTJSC::JSValue, QTJSC::ArgList const&) const (this=0x7ffd9dffd810, exec=0x7ffda45308d8, jsobj=0x7ffda44e7f40, thisValue=..., argList=...) at ../3rdparty/javascriptcore/JavaScriptCore/runtime/CallData.cpp:44
#17 0x00007ffff01b284a in QTJSC::callDefaultValueFunction (propertyName=<optimized out>, object=0x7ffda44e7f00, exec=0x7ffda45308d8) at ../3rdparty/javascriptcore/JavaScriptCore/runtime/JSValue.h:814
#18 QTJSC::JSObject::defaultValue(QTJSC::ExecState*, QTJSC::PreferredPrimitiveType) const (this=0x7ffda44e7f00, exec=0x7ffda45308d8, hint=<optimized out>) at ../3rdparty/javascriptcore/JavaScriptCore/runtime/JSObject.cpp:274
#19 0x00007ffff01b2164 in QTJSC::JSObject::toPrimitive(QTJSC::ExecState*, QTJSC::PreferredPrimitiveType) const (preferredType=QTJSC::PreferString, exec=0x7ffda45308d8, this=<optimized out>) at ../3rdparty/javascriptcore/JavaScriptCore/runtime/JSObject.h:597
#20 QTJSC::JSObject::toString(QTJSC::ExecState*) const (this=<optimized out>, exec=0x7ffda45308d8) at ../3rdparty/javascriptcore/JavaScriptCore/runtime/JSObject.cpp:478
#21 0x00007ffff022f8d2 in QTJSC::JSValue::toString(QTJSC::ExecState*) const (exec=exec@entry=0x7ffda45308d8, this=<optimized out>, this=<optimized out>) at ../3rdparty/javascriptcore/JavaScriptCore/runtime/JSString.h:545
#22 0x00007ffff023ded3 in QScriptEnginePrivate::toString(QTJSC::ExecState*, QTJSC::JSValue) (exec=0x7ffda45308d8, value=...) at api/qscriptengine_p.h:1068
#23 0x00007ffff0238805 in QScriptEnginePrivate::convertValue(QTJSC::ExecState*, QTJSC::JSValue, int, void*) (exec=0x7ffda45308d8, value=..., type=-1644177040, ptr=0x7ffd9dffdb30) at api/qscriptengine.cpp:3246
#24 0x00007ffff025d831 in QScript::delegateQtMethod<QScript::QtMethodIndexReturner>(QTJSC::ExecState*, QTJSC::ArgList const&, QMetaObject const*, int, bool, QScript::QtMethodIndexReturner&, QMetaMethod::MethodType)
    (exec=exec@entry=0x7ffda45308d8, scriptArgs=..., meta=<optimized out>, initialIndex=initialIndex@entry=59, maybeOverloaded=maybeOverloaded@entry=true, delegate=<optimized out>, callType=<optimized out>) at bridge/qscriptqobject.cpp:583
#25 0x00007ffff025f8a9 in QScript::QtFunction::specificIndex(QScriptContext const*) const (this=0x7ffda44c72c0, context=0x7ffda45308d8) at bridge/qscriptqobject.cpp:1048
#26 0x00007ffff0227193 in QScriptContextInfoPrivate::QScriptContextInfoPrivate(QScriptContext const*) (this=0x7ffd60192ea0, context=0x7ffda45308d8) at api/qscriptcontextinfo.cpp:218
#27 0x00007ffff0227412 in QScriptContextInfo::QScriptContextInfo(QScriptContext const*) (this=0x7ffd9dffdea0, context=0x7ffda45308d8) at api/qscriptcontextinfo.cpp:252
#28 0x00007ffff51720a6 in ScriptEngineLoggingAgent::functionEntry(long long) (this=0x16e8a1a0, scriptId=-1) at /home/dale/git/vircadia/vircadia-master/libraries/script-engine/src/ScriptEngineLoggingAgent.cpp:37

So far this is extremely half-baked and guaranteed to run out of stack space right on start due to that last problem. Some help here would be extremely appreciated.

vircadia-build-notifier · 2021-04-04T23:59:40Z

The following links are available:
build (macOS-latest, full)

https://athena-public.s3.eu-west-3.amazonaws.com/builds/PR/vircadia_vircadia/PR1156/Vircadia-PR1156-3c00c3f-_d03d1883.dmg

build (ubuntu-18.04, full)

build (ubuntu-18.04, android)

build (windows-latest, full)

https://athena-public.s3.eu-west-3.amazonaws.com/builds/PR/vircadia_vircadia/PR1156/Vircadia-PR1156-3c00c3f-_d03d1883.exe

daleglass · 2021-04-05T16:27:31Z

Okay, less broken attempt. This shouldn't crash anymore.

vircadia-build-notifier · 2021-04-05T18:18:07Z

The following links are available:
build (ubuntu-18.04, full)

build (macOS-latest, full)

https://athena-public.s3.eu-west-3.amazonaws.com/builds/PR/vircadia_vircadia/PR1156/Vircadia-PR1156-8c8b6a2-_b6271abb.dmg

build (windows-latest, full)

https://athena-public.s3.eu-west-3.amazonaws.com/builds/PR/vircadia_vircadia/PR1156/Vircadia-PR1156-8c8b6a2-_b6271abb.exe

build (ubuntu-18.04, android)

ctrlaltdavid · 2021-04-10T23:41:50Z

Suggestions:

Make this facility opt-in so that it doesn't slow script operations in normal usage. Perhaps a Developer menu item.
Make it log to the program log so that users can provide program logs when tracking down problems. (On Windows it currently only outputs to the Visual Studio "output" when running under the debugger.

ctrlaltdavid · 2021-04-15T08:37:09Z

interface/src/Application.cpp

@@ -7652,6 +7653,9 @@ void Application::registerScriptEngineWithApplicationServices(const ScriptEngine
    connect(scriptEngine.data(), &ScriptEngine::infoMessage, scriptEngines, &ScriptEngines::onInfoMessage);
    connect(scriptEngine.data(), &ScriptEngine::clearDebugWindow, scriptEngines, &ScriptEngines::onClearDebugWindow);

+
+    ScriptEngineLoggingAgent *scriptLogger = new ScriptEngineLoggingAgent(scriptEngine.data());


Suggested change

ScriptEngineLoggingAgent *scriptLogger = new ScriptEngineLoggingAgent(scriptEngine.data());

ScriptEngineLoggingAgent* scriptLogger = new ScriptEngineLoggingAgent(scriptEngine.data());

ctrlaltdavid · 2021-04-15T08:38:15Z

libraries/script-engine/src/ScriptEngineLoggingAgent.cpp

+//  script-engine/src
+//
+//  Created by Dale Glass on 04/04/2021.
+//  Copyright 2021 Vircadia Contributors


Suggested change

// Copyright 2021 Vircadia Contributors

// Copyright 2021 Vircadia contributors.

ctrlaltdavid · 2021-04-15T08:39:16Z

libraries/script-engine/src/ScriptEngineLoggingAgent.cpp

+void ScriptEngineLoggingAgent::functionEntry(qint64 scriptId) {
+    if ( scriptId != -1) {


Suggested change

void ScriptEngineLoggingAgent::functionEntry(qint64 scriptId) {

if ( scriptId != -1) {

void ScriptEngineLoggingAgent::functionEntry(qint64 scriptID) {

if (scriptID != -1) {

ctrlaltdavid · 2021-04-15T08:39:45Z

libraries/script-engine/src/ScriptEngineLoggingAgent.cpp

+void ScriptEngineLoggingAgent::functionExit(qint64 scriptId, const QScriptValue &returnValue) {
+    if ( scriptId != -1) {


Suggested change

void ScriptEngineLoggingAgent::functionExit(qint64 scriptId, const QScriptValue &returnValue) {

if ( scriptId != -1) {

void ScriptEngineLoggingAgent::functionExit(qint64 scriptID, const QScriptValue& returnValue) {

if (scriptID != -1) {

ctrlaltdavid · 2021-04-15T08:39:59Z

libraries/script-engine/src/ScriptEngineLoggingAgent.h

+//  script-engine/src
+//
+//  Created by Dale Glass on 04/04/2021.
+//  Copyright 2021 Vircadia Contributors


Suggested change

// Copyright 2021 Vircadia Contributors

// Copyright 2021 Vircadia contributors.

ctrlaltdavid · 2021-04-15T08:44:55Z

libraries/shared/src/ScriptContextHelper.cpp

+QStringList ScriptContextHelper::get() {
+    QList<QStringList> data = _context.localData();
+
+    if ( data.isEmpty() ) {


Suggested change

if ( data.isEmpty() ) {

if (data.isEmpty()) {

ctrlaltdavid · 2021-04-15T08:45:22Z

libraries/shared/src/ScriptContextHelper.cpp

+
+    //return _context.localData();


Suggested change

//return _context.localData();

ctrlaltdavid · 2021-04-15T08:45:42Z

libraries/shared/src/ScriptContextHelper.h

+//  shared/src
+//
+//  Created by Dale Glass on 04/04/2021.
+//  Copyright 2021 Vircadia Contributors


Suggested change

// Copyright 2021 Vircadia Contributors

// Copyright 2021 Vircadia contributors.

ctrlaltdavid · 2021-04-15T08:52:11Z

libraries/shared/src/ScriptContextHelper.h

+
+class ScriptContextHelper {
+public:
+    static void push(QStringList context);


Suggested change

static void push(QStringList context);

static void push(const QStringList& context);

ctrlaltdavid · 2021-04-15T08:52:34Z

libraries/shared/src/ScriptContextHelper.cpp

+
+QThreadStorage<QList<QStringList>> ScriptContextHelper::_context;
+
+void  ScriptContextHelper::push(QStringList context) {


Suggested change

void ScriptContextHelper::push(QStringList context) {

void ScriptContextHelper::push(const QStringList& context) {

HifiExperiments · 2021-04-23T02:12:07Z

interface/src/Application.cpp

@@ -7652,6 +7653,9 @@ void Application::registerScriptEngineWithApplicationServices(const ScriptEngine
    connect(scriptEngine.data(), &ScriptEngine::infoMessage, scriptEngines, &ScriptEngines::onInfoMessage);
    connect(scriptEngine.data(), &ScriptEngine::clearDebugWindow, scriptEngines, &ScriptEngines::onClearDebugWindow);

+
+    ScriptEngineLoggingAgent *scriptLogger = new ScriptEngineLoggingAgent(scriptEngine.data());
+    scriptEngine->setAgent(scriptLogger);


I agree with david that it would be good to disable this by default so it doesn’t affect the performance of normal scripts. it seems like it adds overhead to every single function call.

I also wonder, is this agent automatically deleted when the script engine dies? what about the associated thread local storage?

Good point, I'll look into it.

odysseus654 · 2021-05-23T02:59:32Z

Okay, finally reviewed this after needing to to so for... a while. My thoughts...

Is there a reason why the backtrace is being retrieved from the QScriptContext before the exception occurs? I would think that just remembering the context (which smells like a stack-based animal and therefore isn't to be trusted after the function occurs) would be a fairly lightweight action.
Most of the work here seems to be because the error handler would not have direct access to the QScriptEngine that may have generated the context and so could not use QScriptEngine::currentContext. However this information may be available through adding a QCallable reference.
I will likely be adapting the "agent" interface here in an attempt to proxy the QCallable interface (as a bunch of static functions using TLS) in an engine-independent manner.

odysseus654 · 2021-09-20T07:26:04Z

I'm still having an eye towards this, especially after #1200 lands (which does use at least part of the technique described here).

The only part of the patch I'm interested in here for surviving are the changes to libraries/shared/src/LogHandler.cpp, however I'm unsure how this would work as I'm trying to avoid adding dependencies from shared to script-engine

stale · 2022-05-05T19:02:14Z

Hello! Is this still an issue?

Initial, horribly broken attempt

d03d188

daleglass added enhancement New feature or request help wanted Extra attention is needed labels Apr 4, 2021

Avoid crash by holding a lock to detect recursion

b6271ab

digisomni added the needs CR (code review) label Apr 8, 2021

Output to VS debug window

2ea18eb

ctrlaltdavid requested changes Apr 15, 2021

View reviewed changes

HifiExperiments requested changes Apr 23, 2021

View reviewed changes

daleglass mentioned this pull request Apr 24, 2021

Project: Script Engine Upgrade #1180

Open

daleglass mentioned this pull request May 9, 2021

Drop remaining references to "QScriptEngineDebugger". #1206

Merged

digisomni added the dormant This PR is on hold but has interest/use surrounding it. label Nov 6, 2021

stale bot added the stale Issue / PR has not had activity label May 5, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Obtain script backtrace when a log event is generated in C++ code #1156

Obtain script backtrace when a log event is generated in C++ code #1156

daleglass commented Apr 4, 2021

vircadia-build-notifier commented Apr 4, 2021

daleglass commented Apr 5, 2021

vircadia-build-notifier commented Apr 5, 2021

ctrlaltdavid commented Apr 10, 2021

ctrlaltdavid Apr 15, 2021

ctrlaltdavid Apr 15, 2021

ctrlaltdavid Apr 15, 2021 •

edited

ctrlaltdavid Apr 15, 2021 •

edited

ctrlaltdavid Apr 15, 2021

ctrlaltdavid Apr 15, 2021

ctrlaltdavid Apr 15, 2021

ctrlaltdavid Apr 15, 2021

ctrlaltdavid Apr 15, 2021

ctrlaltdavid Apr 15, 2021

HifiExperiments Apr 23, 2021

daleglass Apr 23, 2021

odysseus654 commented May 23, 2021

odysseus654 commented Sep 20, 2021

stale bot commented May 5, 2022

	ScriptEngineLoggingAgent *scriptLogger = new ScriptEngineLoggingAgent(scriptEngine.data());
	ScriptEngineLoggingAgent* scriptLogger = new ScriptEngineLoggingAgent(scriptEngine.data());

	// Copyright 2021 Vircadia Contributors
	// Copyright 2021 Vircadia contributors.

		void ScriptEngineLoggingAgent::functionEntry(qint64 scriptId) {
		if ( scriptId != -1) {

	static void push(QStringList context);
	static void push(const QStringList& context);


		QThreadStorage<QList<QStringList>> ScriptContextHelper::_context;

		void ScriptContextHelper::push(QStringList context) {

	void ScriptContextHelper::push(QStringList context) {
	void ScriptContextHelper::push(const QStringList& context) {

Obtain script backtrace when a log event is generated in C++ code #1156

Are you sure you want to change the base?

Obtain script backtrace when a log event is generated in C++ code #1156

Conversation

daleglass commented Apr 4, 2021

vircadia-build-notifier commented Apr 4, 2021

daleglass commented Apr 5, 2021

vircadia-build-notifier commented Apr 5, 2021

ctrlaltdavid commented Apr 10, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ctrlaltdavid Apr 15, 2021 • edited

Choose a reason for hiding this comment

ctrlaltdavid Apr 15, 2021 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

odysseus654 commented May 23, 2021

odysseus654 commented Sep 20, 2021

stale bot commented May 5, 2022

ctrlaltdavid Apr 15, 2021 •

edited

ctrlaltdavid Apr 15, 2021 •

edited