LOG$ObjectTypes.txt is broken when target application uses custom class loaders

shimastripe commented 6 years ago

Environment

selogger version: 14 May 2015 [9bf6fb1 @ master brunch] target Java Application: jEdit (http://jedit.org/) version:5.3.0

I run the selogger on the following two OSs.

macOS:

$ uname -a
Darwin tklab143.sa.cs-private 16.7.0 Darwin Kernel Version 16.7.0: Mon Nov 13 21:56:25 PST 2017; root:xnu-3789.72.11~1/RELEASE_X86_64 x86_64

$ java -version
java version "1.8.0_51"
Java(TM) SE Runtime Environment (build 1.8.0_51-b16)
Java HotSpot(TM) 64-Bit Server VM (build 25.51-b03, mixed mode)

Linux:

$uname -a
Linux rigatoni 4.4.0-104-generic #127-Ubuntu SMP Mon Dec 11 12:16:42 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

$ java -version
openjdk version "1.8.0_151"
OpenJDK Runtime Environment (build 1.8.0_151-8u151-b12-0ubuntu0.16.04.2-b12)
OpenJDK 64-Bit Server VM (build 25.151-b12, mixed mode)

Problem

On the macOS, I attemped to read execution traces with EventReader, but an assertion (objId == count) failed in ObjectTypeMap#register (line 52). I found some lines in LOG$ObjectTypes01.txt were corrupted.

19499,24
19500,19501,10
19502,22
19503,22
19504,10
19505,10
19506,10
19507,10
356
19508,10
19509,24
19510,10
19511,172
19512,10
19513,10
19514,10
19515,351
19516,353
19517,354
19518,10
19519,24
19520,10
19521,24
19522,19523,10
19524,351
19525,22
19526,10
19527,22
19528,10
19529,10
19530,76
357
19531,10

On Ubuntu, I succeeded in reading the execution traces without the above error, and I confirmed LOG$ObjectTypes01.txt was not broken. The types of the corrupted IDs (356 and 357) are as follows (extracted from LOG$Types.txt):

356,macosx.MacOSXPlugin,jeditresource:/MacOSX.jar!/macosx/MacOSXPlugin.class,355,-1
357,macosx.MacOSXPlugin$1,jeditresource:/MacOSX.jar!/macosx/MacOSXPlugin$1.class,9,-1

Here, I provide some debug information I found. https://github.com/takashi-ishio/selogger/blob/0df862637705017a088cb78cd5b4866ebbffe49d/trunk/src/selogger/logging/TypeIdMap.java#L45-L63

I commented out the line 56, and ran the woven application again. Then, the assertion error did not arise and I confirmed the LOG$ObjectTypes01.txt were not corrupted. TypeIdMap#getClassLoacation(), which is invoked at line 56, calls some ClassLoader methods.

So I think there might be a problem with logging a class loader. Actually, macosx.MacOSXPlugin was loaded by a custom class loader (org.gjt.sp.jedit.JARClassLoader) and the custom class loader was instrumented for logging.

How to reproduce the assertion error

weaving option

# place the source codes of jEdit in the ${PRJ_DIR} directory
SELOGGER_DIR="/Users/shimastripe/selogger"
PRJ_DIR="/Users/shimastripe/jEdit"
cd ${PRJ_DIR}
ant retrieve
ant build
ant docs-html
java -cp\
        ${SELOGGER_DIR}/selogger-may-14-2015-9bf6fb1.jar:${SELOGGER_DIR}/asm-5.0.3.jar:${SELOGGER_DIR}/asm-analysis-5.0.3.jar:${SELOGGER_DIR}/asm-commons-5.0.3.jar:${SELOGGER_DIR}/asm-tree-5.0.3.jar:${SELOGGER_DIR}/asm-util-5.0.3.jar:${SELOGGER_DIR}/commons-lang3-3.1.jar:${SELOGGER_DIR}/trove-3.0.2.jar:${PRJ_DIR}/build/classes/core:${PRJ_DIR}/lib/compile/jsr305.jar:/Library/Java/JavaVirtualMachines/jdk1.8.0_51.jdk/Contents/Home/lib/tools.jar\
        selogger.weaver.TraceWeaver\
        -jdk17\
        -output=output/tracer/weaver_output\
        -ignoreError\
        -jardir ${PRJ_DIR}/build/classes/core

trace option

cd ${PRJ_DIR}/build
java -Xms2g -Xmx7g\
        -cp ${SELOGGER_DIR}/selogger-may-14-2015-9bf6fb1.jar:${PRJ_DIR}/output/tracer/weaver_output:.:./jedit.jar \
        -Dselogger.dir=${PRJ_DIR}/output/tracer/execution_trace \
        -Dselogger.threads=4 \
        -Dselogger.output=fixed-compress \
        org.gjt.sp.jedit.jEdit \
        -settings=settings
# After the jEdit application is launched, just quit the application by closing the application window.

takashi-ishio commented 6 years ago

Thank you for your kind bug report in detail. Although I could not reproduce the bug on my environment (Windows), it is likely caused by a recursive call path: LogWriter.getObjectId -> ObjectIdFile.newObjectId -> TypeIdMap.getTypeIdString -> TypeIdMap.createTypeRecord -> Classloader's getResource -> (injected logging code) -> LogWriter.getObjectId.

I will change selogger to avoid the recursive call itself. I think you can temporarily avoid the problem in case of jEdit by changing ObjectIdFile.newObjectId as follows:

    protected void onNewObject(Object o, long id) {
            String typeId = typeToId.getTypeIdString(o.getClass());
            objectIdList.write(Long.toString(id));
            objectIdList.write(",");
            objectIdList.write(typeId);
            objectIdList.write(lineSeparator);

shimastripe commented 6 years ago

Thank you for providing a workaround. Unfortunately, it resulted in producing the non-sequencial object IDs as follows. (See around the corrupted IDs of 356 and 357)

So the assertion (objId == count) still failed at ObjectTypeMap#register (line 52).

(Anyway,) I'm now using selogger on Ubuntu instead of macOS, so I'm not much in a hurry on this issue. Thank you!

takashi-ishio commented 6 years ago

I could replicate the problem on Windows by installing a jEdit plug-in using the Plug-in menu of jEdit. The cause is a custom class loader's getResource method used by TypeIdMap. The method generated a new object ID during generation of a type id. The new version firstly generates a new type id, and then generates a new object ID in order to keep the sequential order of id generation.

I also fixed the same problem in the latest version of develop branch. Thank you for the bug report!

shimastripe commented 6 years ago

I confirmed the LOG$ObjectTypes01.txt is no longer corrupted in the latest version [0c95166] of selogger! Thank you for your swift action. 🙇

takashi-ishio / selogger