Improve debug/tracing output.

- add state machine instance to more messages
- dump event contents when submitting/routing an event

Change-Id: I6b81f8613c147820f7330b3e036c5588cec0b495
Reviewed-by: Ulf Hermann <ulf.hermann@theqtcompany.com>

6 files changed, 56 insertions, 24 deletions

diff --git a/src/scxml/qscxmlecmascriptdatamodel.cpp b/src/scxml/qscxmlecmascriptdatamodel.cpp
index 54c2dfb..6b6dc60 100644
--- a/src/scxml/qscxmlecmascriptdatamodel.cpp
+++ b/src/scxml/qscxmlecmascriptdatamodel.cpp
@@ -121,7 +121,7 @@ public:
         Q_ASSERT(engine());
         dataModel = engine()->globalObject();
 
-        qCDebug(qscxmlLog) << "initializing the datamodel";
+        qCDebug(qscxmlLog) << stateMachine() << "initializing the datamodel";
         setupSystemVariables();
     }
 
diff --git a/src/scxml/qscxmlevent.cpp b/src/scxml/qscxmlevent.cpp
index 11677e1..3129063 100644
--- a/src/scxml/qscxmlevent.cpp
+++ b/src/scxml/qscxmlevent.cpp
@@ -41,6 +41,9 @@
 #include "qscxmlevent_p.h"
 #include "qscxmlstatemachine_p.h"
 
+#include <QJsonDocument>
+#include <QJsonObject>
+
 QT_BEGIN_NAMESPACE
 
 using namespace QScxmlExecutableContent;
@@ -564,4 +567,22 @@ void QScxmlEvent::makeIgnorable()
     t = ignoreEventType;
 }
 
+QByteArray QScxmlEventPrivate::debugString(QScxmlEvent *event)
+{
+    if (event == nullptr) {
+        return "<null>";
+    }
+
+    QJsonObject o;
+    o[QStringLiteral("name")] = event->name();
+    o[QStringLiteral("name")] = event->scxmlType();
+    o[QStringLiteral("name")] = event->sendId();
+    o[QStringLiteral("name")] = event->origin();
+    o[QStringLiteral("name")] = event->originType();
+    o[QStringLiteral("name")] = event->invokeId();
+    o[QStringLiteral("data")] = QJsonValue::fromVariant(event->data());
+
+    return QJsonDocument(o).toJson(QJsonDocument::Compact);
+}
+
 QT_END_NAMESPACE
diff --git a/src/scxml/qscxmlevent_p.h b/src/scxml/qscxmlevent_p.h
index 72d11d6..685208c 100644
--- a/src/scxml/qscxmlevent_p.h
+++ b/src/scxml/qscxmlevent_p.h
@@ -168,6 +168,8 @@ public:
     QString originType; // type to answer by setting the type of send, empty for internal and platform events
     QString invokeId; // id of the invocation that triggered the child process if this was invoked
     int delayInMiliSecs;
+
+    static QByteArray debugString(QScxmlEvent *event);
 };
 
 QT_END_NAMESPACE
diff --git a/src/scxml/qscxmlexecutablecontent.cpp b/src/scxml/qscxmlexecutablecontent.cpp
index 279aa52..a11b4ca 100644
--- a/src/scxml/qscxmlexecutablecontent.cpp
+++ b/src/scxml/qscxmlexecutablecontent.cpp
@@ -111,35 +111,35 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
     auto instr = reinterpret_cast<Instruction *>(ip);
     switch (instr->instructionType) {
     case Instruction::Sequence: {
-        qCDebug(qscxmlLog) << "Executing sequence step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing sequence step";
         InstructionSequence *sequence = reinterpret_cast<InstructionSequence *>(instr);
         ip = sequence->instructions();
         Instructions end = ip + sequence->entryCount;
         while (ip < end) {
             if (!step(ip)) {
                 ip = end;
-                qCDebug(qscxmlLog) << "Finished sequence step UNsuccessfully";
+                qCDebug(qscxmlLog) << stateMachine << "Finished sequence step UNsuccessfully";
                 return false;
             }
         }
-        qCDebug(qscxmlLog) << "Finished sequence step successfully";
+        qCDebug(qscxmlLog) << stateMachine << "Finished sequence step successfully";
         return true;
     }
 
     case Instruction::Sequences: {
-        qCDebug(qscxmlLog) << "Executing sequences step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing sequences step";
         InstructionSequences *sequences = reinterpret_cast<InstructionSequences *>(instr);
         ip += sequences->size();
         for (int i = 0; i != sequences->sequenceCount; ++i) {
             Instructions sequence = sequences->at(i);
             step(sequence);
         }
-        qCDebug(qscxmlLog) << "Finished sequences step";
+        qCDebug(qscxmlLog) << stateMachine << "Finished sequences step";
         return true;
     }
 
     case Instruction::Send: {
-        qCDebug(qscxmlLog) << "Executing send step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing send step";
         Send *send = reinterpret_cast<Send *>(instr);
         ip += send->size();
 
@@ -160,7 +160,7 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
             if (msecs >= 0) {
                 event->setDelay(msecs);
             } else {
-                qCDebug(qscxmlLog) << "failed to parse delay time" << delay;
+                qCDebug(qscxmlLog) << stateMachine << "failed to parse delay time" << delay;
                 return false;
             }
         }
@@ -170,7 +170,7 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
     }
 
     case Instruction::JavaScript: {
-        qCDebug(qscxmlLog) << "Executing script step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing script step";
         JavaScript *javascript = reinterpret_cast<JavaScript *>(instr);
         ip += javascript->size();
         bool ok = true;
@@ -179,7 +179,7 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
     }
 
     case Instruction::If: {
-        qCDebug(qscxmlLog) << "Executing if step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing if step";
         If *_if = reinterpret_cast<If *>(instr);
         ip += _if->size();
         auto blocks = _if->blocks();
@@ -188,7 +188,7 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
             if (dataModel->evaluateToBool(_if->conditions.at(i), &ok) && ok) {
                 Instructions block = blocks->at(i);
                 bool res = step(block);
-                qCDebug(qscxmlLog) << "Finished if step";
+                qCDebug(qscxmlLog) << stateMachine << "Finished if step";
                 return res;
             }
         }
@@ -220,7 +220,7 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
             }
         };
 
-        qCDebug(qscxmlLog) << "Executing foreach step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing foreach step";
         Foreach *foreach = reinterpret_cast<Foreach *>(instr);
         Instructions loopStart = foreach->blockstart();
         ip += foreach->size();
@@ -231,7 +231,7 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
     }
 
     case Instruction::Raise: {
-        qCDebug(qscxmlLog) << "Executing raise step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing raise step";
         Raise *raise = reinterpret_cast<Raise *>(instr);
         ip += raise->size();
         auto name = tableData->string(raise->event);
@@ -243,7 +243,7 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
     }
 
     case Instruction::Log: {
-        qCDebug(qscxmlLog) << "Executing log step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing log step";
         Log *log = reinterpret_cast<Log *>(instr);
         ip += log->size();
         bool ok = true;
@@ -261,7 +261,7 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
     }
 
     case Instruction::Cancel: {
-        qCDebug(qscxmlLog) << "Executing cancel step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing cancel step";
         Cancel *cancel = reinterpret_cast<Cancel *>(instr);
         ip += cancel->size();
         QString e = tableData->string(cancel->sendid);
@@ -274,7 +274,7 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
     }
 
     case Instruction::Assign: {
-        qCDebug(qscxmlLog) << "Executing assign step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing assign step";
         Assign *assign = reinterpret_cast<Assign *>(instr);
         ip += assign->size();
         bool ok = true;
@@ -283,7 +283,7 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
     }
 
     case Instruction::Initialize: {
-        qCDebug(qscxmlLog) << "Executing initialize step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing initialize step";
         Initialize *init = reinterpret_cast<Initialize *>(instr);
         ip += init->size();
         bool ok = true;
@@ -292,12 +292,12 @@ bool QScxmlExecutionEngine::step(Instructions &ip)
     }
 
     case Instruction::DoneData: {
-        qCDebug(qscxmlLog) << "Executing DoneData step";
+        qCDebug(qscxmlLog) << stateMachine << "Executing DoneData step";
         DoneData *doneData = reinterpret_cast<DoneData *>(instr);
 
         QString eventName = QStringLiteral("done.state.") + extraData.toString();
         QScxmlEventBuilder event(stateMachine, eventName, doneData);
-        qCDebug(qscxmlLog) << "submitting event" << eventName;
+        qCDebug(qscxmlLog) << stateMachine << "submitting event" << eventName;
         stateMachine->submitEvent(event());
         return true;
     }
diff --git a/src/scxml/qscxmlinvokableservice.cpp b/src/scxml/qscxmlinvokableservice.cpp
index ca64cdb..d473915 100644
--- a/src/scxml/qscxmlinvokableservice.cpp
+++ b/src/scxml/qscxmlinvokableservice.cpp
@@ -79,8 +79,14 @@ QScxmlStateMachine *QScxmlInvokableService::parentStateMachine() const
 
 void QScxmlInvokableService::finalize()
 {
-    auto smp = QScxmlStateMachinePrivate::get(parentStateMachine());
-    smp->m_executionEngine->execute(d->service->finalizeContent());
+    QScxmlExecutableContent::ContainerId finalize = d->service->finalizeContent();
+
+    if (finalize != QScxmlExecutableContent::NoInstruction) {
+        auto psm = parentStateMachine();
+        qCDebug(qscxmlLog) << psm << "running finalize on event";
+        auto smp = QScxmlStateMachinePrivate::get(psm);
+        smp->m_executionEngine->execute(finalize);
+    }
 }
 
 QScxmlInvokableServiceFactory *QScxmlInvokableService::service() const
diff --git a/src/scxml/qscxmlstatemachine.cpp b/src/scxml/qscxmlstatemachine.cpp
index 2522ade..78a8542 100644
--- a/src/scxml/qscxmlstatemachine.cpp
+++ b/src/scxml/qscxmlstatemachine.cpp
@@ -1104,15 +1104,18 @@ void QScxmlStateMachine::submitEvent(QScxmlEvent *event)
         return;
 
     if (event->delay() > 0) {
-        qCDebug(qscxmlLog) << this << ": submitting event" << event->name()
-                          << "with delay" << event->delay() << "ms"
-                          << "and sendid" << event->sendId();
+        qCDebug(qscxmlLog) << this << "submitting event" << event->name()
+                           << "with delay" << event->delay() << "ms:"
+                           << QScxmlEventPrivate::debugString(event).constData();
 
         Q_ASSERT(event->eventType() == QScxmlEvent::ExternalEvent);
         int id = d->m_qStateMachine->postDelayedEvent(event, event->delay());
 
         qCDebug(qscxmlLog) << this << ": delayed event" << event->name() << "(" << event << ") got id:" << id;
     } else {
+        qCDebug(qscxmlLog) << this << "submitting event" << event->name()
+                           << ":" << QScxmlEventPrivate::debugString(event).constData();
+
         d->routeEvent(event);
     }
 }