[KIEKER-339] Event traces containing only calls cannot be reconstructed

JIRA Issue: KIEKER-339 Event traces containing only calls cannot be reconstructed Original Reporter: Andre van Hoorn

The [^kieker-dep-problem.zip attached monitoring log], provided by Christian, includes traces using the following event types:

avanhoorn@avanhoorn-thinkpad:0:/tmp/d $ cat kieker-20120913-090816050-UTC-chw-PC-KIEKER/kieker.map 
$0=kieker.common.record.flow.trace.Trace
$1=kieker.common.record.flow.trace.operation.CallOperationEvent

Running the trace analysis tool, yields:

avanhoorn@avanhoorn-thinkpad:0:/tmp/d $ ~/git_work/kieker/bin/trace-analysis.sh --inputdirs kieker-20120913-090816050-UTC-chw-PC-KIEKER/ --outputdir out --plot-Deployment-Sequence-Diagrams --plot-Call-Trees --plot-Deployment-Operation-Dependency-Graph --print-invalid-Execution-Traces

...

#
# Plugin: Trace reconstruction (execution records -> execution traces)
Trace processing summary: 0 total; 0 succeeded; 0 failed.

#
# Plugin: Trace reconstruction (event record traces -> execution traces)
Trace processing summary: 0 total; 0 succeeded; 0 failed.

The kieker.log shows no errors:

avanhoorn@avanhoorn-thinkpad:0:/tmp/d $ cat kieker.log 
0    WARN  [main] kieker.tools.traceAnalysis.TraceAnalysisTool     - EventTrace2ExecutionTraceFilter doesn't provide an output port for invalid execution traces, yet
46   INFO  [Thread-2] kieker.analysis.plugin.reader.filesystem.FSDirectoryReader     - < Loading /tmp/d/kieker-20120913-090816050-UTC-chw-PC-KIEKER/kieker-20120913-090816095-UTC--000-Thread-1.dat
84   INFO  [main]    kieker.analysis.AnalysisController     - Terminating analysis.
85   INFO  [main] kieker.analysis.plugin.reader.filesystem.FSReader     - Shutting down reader.
595  INFO  [main] kieker.tools.traceAnalysis.TraceAnalysisTool     - Saved analysis configuration to file '/tmp/d/out/traceAnalysis.kax'

In order to reproduce this, I created the following JUnit test (changeset:9ab3e00c2b33ee54f41f70e88c8cd003afdad23e/kieker-git) --- commented out, in order not to break the build:

TestTraceEventRecords2ExecutionAndMessageTraceFilter.testValidSyncTraceSimpleCallCall().

It uses the sequence of event records, created as follows:

#!java
    public static TraceEventRecords validSyncTraceSimpleCallCall(final long firstTimestamp, final long traceId, final String sessionId, final String hostname) {
        int curOrderIndex = 0;

        // assumed to be uninstrumented: final BeforeOperationEvent entry0_0__bookstore_searchBook; // NOCS
        // assumed to be uninstrumented: final CallOperationEvent call1_1__catalog_getBook; // NOCS
        // assumed to be uninstrumented: final BeforeOperationEvent entry1_1__catalog_getBook; // NOCS
        // assumed to be uninstrumented: final AfterOperationEvent exit1_1__catalog_getBook; // NOCS
        final CallOperationEvent call2_1__crm_getOrders; // NOCS
        // assumed to be uninstrumented: final BeforeOperationEvent entry2_1__crm_getOrders; // NOCS
        final CallOperationEvent call3_2__catalog_getBook; // NOCS
        // assumed to be uninstrumented: final BeforeOperationEvent entry3_2__catalog_getBook; // NOCS
        // assumed to be uninstrumented: final AfterOperationEvent exit3_2__catalog_getBook; // NOCS
        // assumed to be uninstrumented: final AfterOperationEvent exit2_1__crm_getOrders; // NOCS
        // assumed to be uninstrumented: final AfterOperationEvent exit0_0__bookstore_searchBook; // NOCS

        call2_1__crm_getOrders =
                new CallOperationEvent(firstTimestamp + BookstoreEventRecordFactory.TSTAMP_OFFSET_call2_1__crm_getOrders,
                        /* note that we are using the timestamp of the omitted event here! */
                        traceId, curOrderIndex++,
                        BookstoreOperationExecutionRecordFactory.FQ_SIGNATURE_BOOKSTORE_SEARCH_BOOK,
                        BookstoreOperationExecutionRecordFactory.FQ_CLASS_BOOKSTORE,
                        BookstoreOperationExecutionRecordFactory.FQ_SIGNATURE_CRM_GET_ORDERS,
                        BookstoreOperationExecutionRecordFactory.FQ_CLASS_CRM);
        call3_2__catalog_getBook =
                new CallOperationEvent(firstTimestamp + BookstoreEventRecordFactory.TSTAMP_OFFSET_call3_2__catalog_getBook,
                        traceId, curOrderIndex++, BookstoreOperationExecutionRecordFactory.FQ_SIGNATURE_CRM_GET_ORDERS,
                        BookstoreOperationExecutionRecordFactory.FQ_CLASS_CRM,
                        BookstoreOperationExecutionRecordFactory.FQ_SIGNATURE_CATALOG_GET_BOOK,
                        BookstoreOperationExecutionRecordFactory.FQ_CLASS_CATALOG);

        final Trace trace = new Trace(traceId, -1, sessionId, hostname, -1, -1);
        final AbstractTraceEvent[] events = new AbstractTraceEvent[] {
            call2_1__crm_getOrders,
            call3_2__catalog_getBook,
        };
        return new TraceEventRecords(trace, events);
    }

Result of the test:

java.lang.AssertionError: Unexpected execution trace expected:<TraceId 4563 (minTin=1000004 (Thu, 1 Jan 1970 00:00:00 +0000 (UTC)); maxTout=1000006 (Thu, 1 Jan 1970 00:00:00 +0000 (UTC)); maxEss=2):
<4563[0,0] 1000004-1000006 srv090::@1:bookstore.Bookstore.searchBook y2zGAI0VX>
<4563[1,1] 1000004-1000006 srv090::@3:bookstore.CRM.getOrders y2zGAI0VX>
<4563[2,2] 1000006-1000006 srv090::@2:bookstore.Catalog.getBook y2zGAI0VX>
> but was:<TraceId 4563 (minTin=-1 (Thu, 1 Jan 1970 00:00:00 +0000 (UTC)); maxTout=-1 (Thu, 1 Jan 1970 00:00:00 +0000 (UTC)); maxEss=-1):
>
    at org.junit.Assert.fail(Assert.java:93)
    at org.junit.Assert.failNotEquals(Assert.java:647)
    at org.junit.Assert.assertEquals(Assert.java:128)
    at kieker.test.tools.junit.traceAnalysis.filter.flow.TestTraceEventRecords2ExecutionAndMessageTraceFilter.checkTrace(TestTraceEventRecords2ExecutionAndMessageTraceFilter.java:484)
    at ...

The problem seems to be that the trace is defined only by call events.

If such an event trace is wrapped by an entry and exit event, the reconstruction is successful (see TestTraceEventRecords2ExecutionAndMessageTraceFilter.testValidSyncTraceSimpleEntryCallCallExit).

kieker-monitoring / kieker

[KIEKER-339] Event traces containing only calls cannot be reconstructed #1269