From c3f5905b5204105172c9745ee2171c9e0c0c4750 Mon Sep 17 00:00:00 2001 From: Kai Koehne Date: Mon, 13 Feb 2012 14:35:21 +0100 Subject: Console API: Pass context information from js to qt logging framework Log the file, line, function context from the original calls in js. Also print the stack trace as part of one multi-line message. Change-Id: I53836df081f3ce06e9b52ebb647ba172ff6bdbef Reviewed-by: Aurindam Jana --- .../qml/v8/qdeclarativebuiltinfunctions.cpp | 123 +++++++++++++++------ .../tst_qdebugmessageservice.cpp | 30 +---- .../tst_qdeclarativeconsole.cpp | 43 +++---- 3 files changed, 113 insertions(+), 83 deletions(-) diff --git a/src/declarative/qml/v8/qdeclarativebuiltinfunctions.cpp b/src/declarative/qml/v8/qdeclarativebuiltinfunctions.cpp index dbd5408313..12f06e6b76 100644 --- a/src/declarative/qml/v8/qdeclarativebuiltinfunctions.cpp +++ b/src/declarative/qml/v8/qdeclarativebuiltinfunctions.cpp @@ -47,6 +47,7 @@ #include #include #include +#include #include #include @@ -69,9 +70,6 @@ QT_BEGIN_NAMESPACE -// send more information such as file, line etc for console APIs -DEFINE_BOOL_CONFIG_OPTION(qmlConsoleExtended, QML_CONSOLE_EXTENDED) - namespace QDeclarativeBuiltinFunctions { enum ConsoleLogTypes { @@ -80,21 +78,19 @@ enum ConsoleLogTypes { Error }; -static QString extendMessage(const QString &msg) { - if (qmlConsoleExtended()) { - v8::Local stackTrace = v8::StackTrace::CurrentStackTrace(1); - if (stackTrace->GetFrameCount()) { - v8::Local frame = stackTrace->GetFrame(0); - int line = frame->GetLineNumber(); - QString scriptName = QString::fromUtf16(*v8::String::Value(frame->GetScriptName())); - - return QString::fromLatin1("%1 (%2:%3)").arg(msg).arg(scriptName).arg(line); - } +static void jsContext(v8::Handle *file, int *line, v8::Handle *function) { + v8::Local stackTrace = v8::StackTrace::CurrentStackTrace(1); + if (stackTrace->GetFrameCount()) { + v8::Local frame = stackTrace->GetFrame(0); + *file = frame->GetScriptName(); + *line = frame->GetLineNumber(); + *function = frame->GetFunctionName(); } - return msg; } -static void printStack() { +static QString jsStack() { + QStringList stackFrames; + //The v8 default is currently 10 stack frames. v8::Handle stackTrace = v8::StackTrace::CurrentStackTrace(10, v8::StackTrace::kOverview); @@ -102,15 +98,23 @@ static void printStack() { for (int i = 0; i < stackCount; i++) { v8::Local frame = stackTrace->GetFrame(i); - v8::String::Utf8Value func_name(frame->GetFunctionName()); - v8::String::Utf8Value script_name(frame->GetScriptName()); + v8::Handle function(frame->GetFunctionName()); + v8::Handle script(frame->GetScriptName()); int lineNumber = frame->GetLineNumber(); int columnNumber = frame->GetColumn(); - qDebug("%s (%s:%d:%d)\n", *func_name, *script_name, lineNumber, columnNumber); + + QString stackFrame = + QString::fromLatin1("%1 (%2:%3:%4)").arg(QJSConverter::toString(function), + QJSConverter::toString(script), + QString::number(lineNumber), + QString::number(columnNumber)); + stackFrames.append(stackFrame); } + return stackFrames.join(QLatin1String("\n")); } -v8::Handle console(ConsoleLogTypes logType, const v8::Arguments &args) +v8::Handle console(ConsoleLogTypes logType, const v8::Arguments &args, + bool printStack = false) { v8::HandleScope handleScope; @@ -135,17 +139,29 @@ v8::Handle console(ConsoleLogTypes logType, const v8::Arguments &args } } - result = extendMessage(result); + if (printStack) { + result.append(QLatin1String("\n")); + result.append(jsStack()); + } + + v8::Handle fileHandle; + v8::Handle functionHandle; + int line; + + jsContext(&fileHandle, &line, &functionHandle); switch (logType) { case Log: - qDebug("%s", qPrintable(result)); + QMessageLogger(*v8::String::AsciiValue(fileHandle), line, + *v8::String::AsciiValue(functionHandle)).debug("%s", qPrintable(result)); break; case Warn: - qWarning("%s", qPrintable(result)); + QMessageLogger(*v8::String::AsciiValue(fileHandle), line, + *v8::String::AsciiValue(functionHandle)).warning("%s", qPrintable(result)); break; case Error: - qCritical("%s", qPrintable(result)); + QMessageLogger(*v8::String::AsciiValue(fileHandle), line, + *v8::String::AsciiValue(functionHandle)).critical("%s", qPrintable(result)); break; default: break; @@ -183,11 +199,22 @@ v8::Handle consoleProfile(const v8::Arguments &args) Q_UNUSED(args); QString title; + + + v8::Handle file; + v8::Handle function; + int line; + jsContext(&file, &line, &function); + if (QDeclarativeProfilerService::startProfiling()) { QV8ProfilerService::instance()->startProfiling(title); - qDebug("Profiling started."); + + QMessageLogger(*v8::String::AsciiValue(file), line, + *v8::String::AsciiValue(function)).debug("Profiling started."); } else { - qWarning("Profiling is already in progress. First, end current profiling session."); + QMessageLogger(*v8::String::AsciiValue(file), line, + *v8::String::AsciiValue(function)).warning( + "Profiling is already in progress. First, end current profiling session."); } return v8::Undefined(); @@ -201,14 +228,22 @@ v8::Handle consoleProfileEnd(const v8::Arguments &args) Q_UNUSED(args); QString title; + v8::Handle file; + v8::Handle function; + int line; + jsContext(&file, &line, &function); + if (QDeclarativeProfilerService::stopProfiling()) { QV8ProfilerService *profiler = QV8ProfilerService::instance(); profiler->stopProfiling(title); QDeclarativeProfilerService::sendProfilingData(); profiler->sendProfilingData(); - qDebug("Profiling ended."); + + QMessageLogger(*v8::String::AsciiValue(file), line, + *v8::String::AsciiValue(function)).debug("Profiling ended."); } else { - qWarning("Profiling was not started."); + QMessageLogger(*v8::String::AsciiValue(file), line, + *v8::String::AsciiValue(function)).warning("Profiling was not started."); } return v8::Undefined(); @@ -250,14 +285,15 @@ v8::Handle consoleCount(const v8::Arguments &args) v8::Local frame = stackTrace->GetFrame(0); QString scriptName = V8ENGINE()->toString(frame->GetScriptName()); + QString functionName = V8ENGINE()->toString(frame->GetFunctionName()); int line = frame->GetLineNumber(); int column = frame->GetColumn(); int value = V8ENGINE()->consoleCountHelper(scriptName, line, column); QString message = name + QLatin1String(": ") + QString::number(value); - if (qmlConsoleExtended()) - message = QString::fromLatin1("%1 (%2:%3)").arg(message).arg(scriptName).arg(line); - qDebug("%s", qPrintable(message)); + + QMessageLogger(qPrintable(scriptName), line, + qPrintable(functionName)).debug("%s", qPrintable(message)); } return v8::Undefined(); @@ -268,7 +304,15 @@ v8::Handle consoleTrace(const v8::Arguments &args) if (args.Length() != 0) V8THROW_ERROR("console.trace(): Invalid arguments"); - printStack(); + QString stack = jsStack(); + + v8::Handle file; + v8::Handle function; + int line; + jsContext(&file, &line, &function); + + QMessageLogger(*v8::String::AsciiValue(file), line, *v8::String::AsciiValue(function)).debug( + "%s", qPrintable(stack)); return v8::Undefined(); } @@ -292,9 +336,16 @@ v8::Handle consoleAssert(const v8::Arguments &args) message.append(V8ENGINE()->toString(value->ToString())); } - message = extendMessage(message); - qCritical("%s", qPrintable(message)); - printStack(); + QString stack = jsStack(); + + v8::Handle file; + v8::Handle function; + int line; + jsContext(&file, &line, &function); + + QMessageLogger(*v8::String::AsciiValue(file), line, *v8::String::AsciiValue(function)).critical( + "%s\n%s", qPrintable(message), qPrintable(stack)); + } return v8::Undefined(); } @@ -303,8 +354,8 @@ v8::Handle consoleException(const v8::Arguments &args) { if (args.Length() == 0) V8THROW_ERROR("console.exception(): Missing argument"); - console(Error, args); - printStack(); + + console(Error, args, true); return v8::Undefined(); } diff --git a/tests/auto/declarative/debugger/qdebugmessageservice/tst_qdebugmessageservice.cpp b/tests/auto/declarative/debugger/qdebugmessageservice/tst_qdebugmessageservice.cpp index 07e744dc58..625e038882 100644 --- a/tests/auto/declarative/debugger/qdebugmessageservice/tst_qdebugmessageservice.cpp +++ b/tests/auto/declarative/debugger/qdebugmessageservice/tst_qdebugmessageservice.cpp @@ -59,7 +59,7 @@ class tst_QDebugMessageService : public QDeclarativeDataTest public: tst_QDebugMessageService(); - void init(bool extendedOutput); + void init(); private slots: void initTestCase(); @@ -68,7 +68,6 @@ private slots: void cleanup(); void retrieveDebugOutput(); - void retrieveDebugOutputExtended(); private: QDeclarativeDebugProcess *m_process; @@ -165,14 +164,12 @@ void tst_QDebugMessageService::cleanupTestCase() delete m_connection; } -void tst_QDebugMessageService::init(bool extendedOutput) +void tst_QDebugMessageService::init() { m_connection = new QDeclarativeDebugConnection(); m_process = new QDeclarativeDebugProcess(QLibraryInfo::location(QLibraryInfo::BinariesPath) + "/qmlscene"); m_client = new QDeclarativeDebugMsgClient(m_connection); - if (extendedOutput) - m_process->setEnvironment(QProcess::systemEnvironment() << "QML_CONSOLE_EXTENDED=1"); m_process->start(QStringList() << QLatin1String(NORMALMODE) << QDeclarativeDataTest::instance()->testFile(QMLFILE)); if (!m_process->waitForSessionStart()) { QFAIL(QString("Could not launch app. Application output: \n%1").arg(m_process->output()).toAscii()); @@ -204,7 +201,7 @@ void tst_QDebugMessageService::cleanup() void tst_QDebugMessageService::retrieveDebugOutput() { - init(false); + init(); int maxTries = 2; while ((m_client->logBuffer.size() < 2) @@ -217,27 +214,6 @@ void tst_QDebugMessageService::retrieveDebugOutput() QVERIFY(m_client->logBuffer.contains(LogEntry(QtDebugMsg, QLatin1String("console.count: 1")))); } -void tst_QDebugMessageService::retrieveDebugOutputExtended() -{ - init(true); - - int maxTries = 2; - while ((m_client->logBuffer.size() < 2) - || (maxTries-- > 0)) - QDeclarativeDebugTest::waitForSignal(m_client, SIGNAL(debugOutput()), 1000); - - QVERIFY(m_client->logBuffer.size() >= 2); - - const QString path = - QUrl::fromLocalFile(QDeclarativeDataTest::instance()->testFile(QMLFILE)).toString(); - - QString logMsg = QString::fromLatin1("console.log (%1:%2)").arg(path).arg(48); - QString countMsg = QString::fromLatin1("console.count: 1 (%1:%2)").arg(path).arg(49); - - QVERIFY(m_client->logBuffer.contains(LogEntry(QtDebugMsg, logMsg))); - QVERIFY(m_client->logBuffer.contains(LogEntry(QtDebugMsg, countMsg))); -} - QTEST_MAIN(tst_QDebugMessageService) #include "tst_qdebugmessageservice.moc" diff --git a/tests/auto/declarative/qdeclarativeconsole/tst_qdeclarativeconsole.cpp b/tests/auto/declarative/qdeclarativeconsole/tst_qdeclarativeconsole.cpp index 7ab1f150ad..f5788dcf55 100644 --- a/tests/auto/declarative/qdeclarativeconsole/tst_qdeclarativeconsole.cpp +++ b/tests/auto/declarative/qdeclarativeconsole/tst_qdeclarativeconsole.cpp @@ -97,10 +97,11 @@ void tst_qdeclarativeconsole::tracing() { QUrl testUrl = testFileUrl("tracing.qml"); - QString trace1 = QString::fromLatin1("tracing (%1:%2:%3)\n").arg(testUrl.toString()).arg(50).arg(17); - QString trace2 = QString::fromLatin1("onCompleted (%1:%2:%3)\n").arg(testUrl.toString()).arg(54).arg(9); - QTest::ignoreMessage(QtDebugMsg, qPrintable(trace1)); - QTest::ignoreMessage(QtDebugMsg, qPrintable(trace2)); + QString traceText = + QString::fromLatin1("tracing (%1:%2:%3)\n").arg(testUrl.toString()).arg(50).arg(17) + + QString::fromLatin1("onCompleted (%1:%2:%3)").arg(testUrl.toString()).arg(54).arg(9); + + QTest::ignoreMessage(QtDebugMsg, qPrintable(traceText)); QDeclarativeComponent component(&engine, testUrl); QObject *object = component.create(); @@ -127,14 +128,15 @@ void tst_qdeclarativeconsole::assert() QUrl testUrl = testFileUrl("assert.qml"); // assert() - QTest::ignoreMessage(QtCriticalMsg, "This will fail"); - QTest::ignoreMessage(QtCriticalMsg, "This will fail too"); - QString trace1 = QString::fromLatin1("onCompleted (%1:%2:%3)\n").arg(testUrl.toString()).arg(54).arg(17); - QString trace2 = QString::fromLatin1("onCompleted (%1:%2:%3)\n").arg(testUrl.toString()).arg(59).arg(9); - QString trace3 = QString::fromLatin1("assertFail (%1:%2:%3)\n").arg(testUrl.toString()).arg(47).arg(17); - QTest::ignoreMessage(QtDebugMsg, qPrintable(trace1)); - QTest::ignoreMessage(QtDebugMsg, qPrintable(trace2)); - QTest::ignoreMessage(QtDebugMsg, qPrintable(trace3)); + QString assert1 = "This will fail\n" + + QString::fromLatin1("onCompleted (%1:%2:%3)").arg(testUrl.toString()).arg(54).arg(17); + + QString assert2 = "This will fail too\n" + + QString::fromLatin1("assertFail (%1:%2:%3)\n").arg(testUrl.toString()).arg(47).arg(17) + + QString::fromLatin1("onCompleted (%1:%2:%3)").arg(testUrl.toString()).arg(59).arg(9); + + QTest::ignoreMessage(QtCriticalMsg, qPrintable(assert1)); + QTest::ignoreMessage(QtCriticalMsg, qPrintable(assert2)); QDeclarativeComponent component(&engine, testUrl); QObject *object = component.create(); @@ -147,14 +149,15 @@ void tst_qdeclarativeconsole::exception() QUrl testUrl = testFileUrl("exception.qml"); // exception() - QTest::ignoreMessage(QtCriticalMsg, "Exception 1"); - QTest::ignoreMessage(QtCriticalMsg, "Exception 2"); - QString trace1 = QString::fromLatin1("onCompleted (%1:%2:%3)\n").arg(testUrl.toString()).arg(51).arg(21); - QString trace2 = QString::fromLatin1("onCompleted (%1:%2:%3)\n").arg(testUrl.toString()).arg(56).arg(9); - QString trace3 = QString::fromLatin1("exceptionFail (%1:%2:%3)\n").arg(testUrl.toString()).arg(46).arg(17); - QTest::ignoreMessage(QtDebugMsg, qPrintable(trace1)); - QTest::ignoreMessage(QtDebugMsg, qPrintable(trace2)); - QTest::ignoreMessage(QtDebugMsg, qPrintable(trace3)); + QString exception1 = "Exception 1\n" + + QString::fromLatin1("onCompleted (%1:%2:%3)").arg(testUrl.toString()).arg(51).arg(21); + + QString exception2 = "Exception 2\n" + + QString::fromLatin1("exceptionFail (%1:%2:%3)\n").arg(testUrl.toString()).arg(46).arg(17) + + QString::fromLatin1("onCompleted (%1:%2:%3)").arg(testUrl.toString()).arg(56).arg(9); + + QTest::ignoreMessage(QtCriticalMsg, qPrintable(exception1)); + QTest::ignoreMessage(QtCriticalMsg, qPrintable(exception2)); QDeclarativeComponent component(&engine, testUrl); QObject *object = component.create(); -- cgit v1.2.3