Libelektra: JNI: Plugin Test Fails

[sanssecours]

Steps to Reproduce the Problem

1. Set the environment variable JAVA_HOME

   export JAVA_HOME=$(/usr/libexec/java_home | tr -d '\n')
   

2. Clone the repository

   git clone https://github.com/ElektraInitiative/libelektra.git
   

3. Create build directory

   mkdir -p build
   

4. Create the build system using the following command

   cd build
   cmake ..                                       \
     -GNinja                                      \
     -DENABLE_ASAN=OFF                            \
     -DENABLE_LOGGER=OFF                          \
     -DENABLE_DEBUG=ON                            \
     -DENABLE_TESTING=ON                          \
     -DCMAKE_EXPORT_COMPILE_COMMANDS=ON           \
     -DBUILD_PDF=OFF                              \
     -DPDFLATEX_COMPILER=`which latexmk`          \
     -DPDFLATEX_COMPILER_OPTIONS='-pdf;-f;-quiet' \
     -DCMAKE_PREFIX_PATH=/usr/local/opt/qt5       \
     -DTOOLS=ALL                                  \
     -DBINDINGS="ALL;-swig_python2;-swig_ruby"    \
     -DPLUGINS="ALL"
   

5. Compile Elektra

   ninja
   

6. Run testmod_jni

   ctest -V -R testmod_jni
   

Expected Result

Everything works fine and the test finishes successfully.

Actual Result

The test fails displaying the output below.

test 61
    Start 61: testmod_jni

61: Test command: Elektra/build/bin/testmod_jni "Elektra/src/plugins/jni"
61: Test timeout computed to be: 1500
61: JNI          TESTS
61: ==================
61:
61: There are 1 warnings
61: buffer is: warnings/#00
61: number: 11
61: description: open of plugin returned unsuccessfully (reason contains plugin, see other warnings for details)
61: ingroup: kdb
61: module:
61: file: ../src/libs/elektra/plugin.c
61: line: 297
61: reason: jni
61: reason:
61: reason:
61: ../src/plugins/jni/testmod_jni.c:31: error in test_helloWorld: warnings in kdbOpen for plugin jni
61: number: 102
61: description: : jni/java error
61: ingroup: : plugin
61: module: : jni
61: at: ../src/plugins/jni/jni.c:236
61: reason: : Cannot find class elektra/plugin/Return
61: mountpoint: :
61: configfile: :
61: ../src/plugins/jni/testmod_jni.c:31: error in test_helloWorld: error in kdbOpen for plugin jni
61: ../src/plugins/jni/testmod_jni.c:31: fatal in test_helloWorld: could not open jni plugin
1/1 Test #61: testmod_jni ......................***Failed    0.09 sec

0% tests passed, 1 tests failed out of 1

Label Time Summary:
memleak    =   0.09 sec (1 test)

Total Test time (real) =   0.10 sec

The following tests FAILED:
     61 - testmod_jni (Failed)
Errors while running CTest

System Information

• Elektra Version: master
• OS: macOS 10.12

[markus2330]

Thank you for reporting the issue!

Could you please do as instructed and set ulimit -c unlimited for core dumps? Without line information it will be hard to track down the bug.

[sanssecours]

Could you please do as instructed and set ulimit -c unlimited for core dumps?

I just did that. The core dump is 6.68GB large. What should I do with this file?

[markus2330]

The backtrace is the most important information. In gdb you get it with bt full. Maybe the backtrace is even included in the hs_err_pid* file.

[sanssecours]

The backtrace is the most important information. In gdb you get it with bt full.

Thank you for the information. I updated the issue description above with the backtrace from lldb.

[markus2330]

Thank you! Seems like open fails and it crashes when calling close later. I tried to fix the segfault, but it won't fix the actual cause of the error during open.

If you want, you can rerun it and post the error. But it is unlikely to give success soon, and we agreed that this plugin is not important. So better to not waste time on it.

[sanssecours]

I tried to fix the segfault, but it won't fix the actual cause of the error during open.

Thank you for taking the time to investigate the problem.

If you want, you can rerun it and post the error.

I just updated the issue description above.

[markus2330]

Thank you!

Seems like the java path is set incorrectly, it should point to the jna jar (in the build directory) via the src/plugins/jni/testmod_jni.h file in the build directory.

If the path is correct in that file maybe the class path passed via -Djava.class.path= is ignored if the environment variable is set?

But as said, I think we should concentrate on more important problems.

[sanssecours]

Seems like the java path is set incorrectly, it should point to the jna jar (in the build directory) via the src/plugins/jni/testmod_jni.h file in the build directory.

I think you are right. According to testmod_jni.h.in the plugin uses the variables

• libelektra_jar and
• jna

. The first is set incorrectly to the absolute path of build/src/bindings/jna/libelektra.jar, the latter is not set at all. As far as I can tell the variable jna was removed in pull request #1238.

[sanssecours]

I looked a little bit further into this. After commit 3b45a0cb, if I replace @jna@ in testmod_jni.h.in with a location of jna.jar (e.g. /Applications/JDownloader.app/Contents/java/app/libs/jna.jar on my machine), then the test reports the following error:

58: Test command: build/bin/testmod_jni "src/plugins/jni"
58: Test timeout computed to be: 1500
58: Exception in thread "main" java.lang.NoSuchMethodError: open
58: JNI          TESTS
58: ==================
58:
58: There are 2 warnings
58: buffer is: warnings/#00
58: number: 101
58: description: java exception caught
58: ingroup: plugin
58: module: jni
58: file: ../src/plugins/jni/jni.c
58: line: 67
58: reason: During "open", exception was thrown: unknown
58: reason:
58: reason:
58: buffer is: warnings/#01/configfile
1/1 Test #58: testmod_jni ......................***Exception: Other  0.41 sec

0% tests passed, 1 tests failed out of 1

Label Time Summary:
memleak    =   0.41 sec (1 test)

Total Test time (real) =   0.46 sec

The following tests FAILED:
     58 - testmod_jni (OTHER_FAULT)
Errors while running CTest

.

[sanssecours]

The newest (yet not merged) version of the code fails with the following error:

58: Test command: build/bin/testmod_jni "src/plugins/jni"
58: Test timeout computed to be: 1500
58: JNI          TESTS
58: ==================
58:
58: testmod_jni(9529,0x7fff93caf340) malloc: *** error for object 0x7fa97e422a50: pointer being freed was not allocated
58: *** set a breakpoint in malloc_error_break to debug
1/1 Test #58: testmod_jni ......................***Exception: Other  0.22 sec

0% tests passed, 1 tests failed out of 1

Label Time Summary:
memleak    =   0.22 sec (1 test)

Total Test time (real) =   0.24 sec

The following tests FAILED:
     58 - testmod_jni (OTHER_FAULT)
Errors while running CTest

. If we enable ASAN Travis shows a more detailed description of the problem:

=================================================================
==21997==ERROR: AddressSanitizer: heap-use-after-free on address 0x606000014518 at pc 0x000106515b8c bp 0x7fff5a748f00 sp 0x7fff5a748ef8
READ of size 8 at 0x606000014518 thread T0
    #0 0x106515b8b in keyGetMeta keymeta.c:423
    #1 0x1054bcf8a in output_warnings tests.c:378
    #2 0x1054c519c in main testmod_jni.c:31
    #3 0x1065c7234 in start (libdyld.dylib:x86_64+0x5234)
0x606000014518 is located 56 bytes inside of 64-byte region [0x6060000144e0,0x606000014520)
freed by thread T0 here:
    #0 0x1071381c6 in wrap_free (libclang_rt.asan_osx_dynamic.dylib:x86_64+0x531c6)
    #1 0x1200894d6 in keyDel key.c:464
    #2 0x12002f133 in ffi_call_unix64 (jna1999621080068927030.tmp:x86_64+0xe133)
    #3 0x7fff5a748417  (<unknown module>)
previously allocated by thread T0 here:
    #0 0x107137ffc in wrap_malloc (libclang_rt.asan_osx_dynamic.dylib:x86_64+0x52ffc)
    #1 0x10650ed75 in elektraMalloc internal.c:241
    #2 0x106511836 in keyNew key.c:85
    #3 0x1054c5133 in main testmod_jni.c:31
    #4 0x1065c7234 in start (libdyld.dylib:x86_64+0x5234)
SUMMARY: AddressSanitizer: heap-use-after-free keymeta.c:423 in keyGetMeta
Shadow bytes around the buggy address:
  0x1c0c00002850: fa fa fa fa 00 00 00 00 00 00 00 00 fa fa fa fa
  0x1c0c00002860: fd fd fd fd fd fd fd fd fa fa fa fa 00 00 00 00
  0x1c0c00002870: 00 00 00 04 fa fa fa fa fd fd fd fd fd fd fd fd
  0x1c0c00002880: fa fa fa fa 00 00 00 00 00 00 06 fa fa fa fa fa
  0x1c0c00002890: 00 00 00 00 00 00 00 00 fa fa fa fa fd fd fd fd
=>0x1c0c000028a0: fd fd fd[fd]fa fa fa fa 00 00 00 00 00 00 00 00
  0x1c0c000028b0: fa fa fa fa fd fd fd fd fd fd fd fd fa fa fa fa
  0x1c0c000028c0: fd fd fd fd fd fd fd fd fa fa fa fa fd fd fd fd
  0x1c0c000028d0: fd fd fd fd fa fa fa fa 00 00 00 00 00 00 00 00
  0x1c0c000028e0: fa fa fa fa 00 00 00 00 00 00 00 fa fa fa fa fa
  0x1c0c000028f0: fd fd fd fd fd fd fd fd fa fa fa fa fd fd fd fd
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==21997==ABORTING
JNI          TESTS
==================

.

[markus2330]

I could not reproduce it (neither with valgrind nor ASAN). Do you know which warning is added (causing the use-after-free?). Maybe a specific warning causes the trouble (checkException gets the warning from JNI).

ELEKTRA_ADD_WARNINGF should actually copy the message to newly allocated memory, maybe the two reported errors are different ones (a use-after-free and a free-of-nonallocated-memory).

"* set a breakpoint in malloc_error_break to debug" might reveal more information (for the free-of-nonallocated-memory which seems to me to be a different different error than you would get with an double-free. Maybe ReleaseStringUTFChars is used wrongly?).

But do not forget that this is very low priority. Please finish everything else first.

[sanssecours]

Do you know which warning is added (causing the use-after-free?).

Nope, if I enable ASAN locally the code crashes with a segmentation fault:

54: Test timeout computed to be: 1500
54: ASAN:DEADLYSIGNAL
54: =================================================================
54: ==31464==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000000 (pc 0x00011bf704f3 bp 0x000109a4a06c sp 0x7ffee6bc0768 T0)
54: ==31464==The signal is caused by a READ memory access.
54: ==31464==Hint: address points to the zero page.
54:     #0 0x11bf704f2  (<unknown module>)
54:
54: ==31464==Register values:
54: rax = 0x0000000000000000  rbx = 0x0000000000000000  rcx = 0x00000000cafebabe  rdx = 0x000000002c100800
54: rdi = 0x0000000109a4a06c  rsi = 0x0000000000000000  rbp = 0x0000000109a4a06c  rsp = 0x00007ffee6bc0768
54:  r8 = 0x00000000ffffffff   r9 = 0x0000000000000060  r10 = 0x00007ffee6bbf570  r11 = 0x0000000000000001
54: r12 = 0x0000000109a4a018  r13 = 0x000061f000007800  r14 = 0x0000000109a08e08  r15 = 0x0000000109a4a028
54: AddressSanitizer can not provide additional info.
54: SUMMARY: AddressSanitizer: SEGV (<unknown module>)
54: ==31464==ABORTING
54: JNI          TESTS
54: ==================
54:
1/1 Test #54: testmod_jni ......................***Exception: Other  0.15 sec

0% tests passed, 1 tests failed out of 1

in JNI_CreateJavaVM (as far as I can tell).

"* set a breakpoint in malloc_error_break to debug" might reveal more information (for the free-of-nonallocated-memory which seems to me to be a different different error than you would get with an double-free.

I just added some logging messages to the code. Looks like keyDel (errorKey) in PLUGIN_OPEN causes the problem.

But do not forget that this is very low priority. Please finish everything else first.

Honestly, I am waiting for either you or Armin to fix this issue.

[markus2330]

Nope, if I enable ASAN locally the code crashes with a segmentation fault:

To find out we would need to enable logging (should print every added warning) or set breakpoints at elektraAddWarning code but see below.

Honestly, I am waiting for either you or Armin to fix this issue.

I did not expect you to fix it. I meant that even answering here or triaging of the bug has low priority. (Unless it happens to someone actually using the plugin.)

[markus2330]

I can reproduce your initial error with Oracle Java 9, the jvm of OpenJDK produces crashes instead.

The jni tests do not find the class Return (implemented in src/bindings/jna/libelektra4j/src/main/java/org/libelektra/plugin/Return.java) anymore:

        Start  81: testmod_jni
 81/190 Test  #81: testmod_jni ..............................***Failed    0.09 sec
JNI          TESTS
==================

There are 1 warnings
buffer is: warnings/#00
number: 11
description: open of plugin returned unsuccessfully (reason contains plugin, see other warnings for details)
ingroup: kdb
module: 
file: /home/markus/Projekte/Elektra/current/src/libs/elektra/plugin.c
line: 294
reason: jni
reason: 
reason: 
/home/markus/Projekte/Elektra/current/src/plugins/jni/testmod_jni.c:31: error in test_helloWorld: warnings in kdbOpen for plugin jni
number: 102
description: : jni/java error
ingroup: : plugin
module: : jni
at: /home/markus/Projekte/Elektra/current/src/plugins/jni/jni.c:236
reason: : Cannot find class org/libelektra/plugin/Return
mountpoint: : 
configfile: : 
/home/markus/Projekte/Elektra/current/src/plugins/jni/testmod_jni.c:31: error in test_helloWorld: error in kdbOpen for plugin jni
/home/markus/Projekte/Elektra/current/src/plugins/jni/testmod_jni.c:31: fatal in test_helloWorld: could not open jni plugin

@e1528532 Is it possible that the restructuring of the jna bindings introduced this problem?

[markus2330]

I reverted 6e4028ea1fac815404e5bce50f6beb75c29d2461 thus it did not help.

@e1528532 Do you have an answer to the question? (Is it possible that the restructuring of the jna bindings introduced this problem?) Does the test case passes on your system?

@sanssecours Should we disable the test case as temporary solution? It is annoying that the test case fails whenever Java is installed.

[sanssecours]

Should we disable the test case as temporary solution? It is annoying that the test case fails whenever Java is installed.

I do not think that is a good solution. The only thing that would help us with is ignoring the actual problem.

[markus2330]

I do not think that is a good solution.

Full ack. I would even say it is no solution at all ;)

The only thing that would help us with is ignoring the actual problem.

It might be nevertheless a good thing to hide low-priority issues. Afaik the jni plugin is not used by anyone. It was/is a prototype to demonstrate that it is possible to use language bindings within a plugin. (The jna binding was greatly improved by @e1528532 so this is not a prototype anymore.)

We currently also exclude many other test cases for various reasons. I agree we need to document all these places and readd them one after another (once the priority changed or the reasons for exclusions are obsolete). We obviously should not have non-experimental components with deactivated test cases.

Alternatively we could warn which test cases were excluded within cmake. But also these warnings are annoying, imho a simple TODO textfile is the most appropriate for such exclusions.

In #1723 there is a proposal to have ENABLE_BROKEN_TESTS which is easy to grep for. It might not replace a todo list, though.

[stale[bot]]

I mark this issue stale as it did not have any activity for one year. I'll close it in two weeks if no further activity occurs. If you want it to be alive again, ping the issue by writing a message here or create a new issue with the remainder of this issue.
Thank you for your contributions :sparkling_heart:

[stale[bot]]

I closed this issue now because it has been inactive for more than one year. If I closed it by mistake, please do not hesitate to reopen it or create a new issue with the remainder of this issue.
Thank you for your contributions :sparkling_heart: