PL/Java VM crash in TransactionListener

hiho …

PL/Java bietet ja uaber SessionManager.current() ein Interface auf die “aktuelle” session …

dieses Interface wiederum hat ne Methode mit der ich einen Listener auf die Transaktion installieren kann - z.B. um auf commit abort und prepare zu lauschen …

nur bloeder weise fuehrt jedweder versuch irgendetwas in diesem Listener zu machen zu einem crash der VM …

z.Bleistift

                @Override
                public void onCommit(org.postgresql.pljava.Session s)
                        throws SQLException {
                    
                    String un = s.getSessionUserName(); <-- crash
                }

hier mal ein blick in das intimste gedärm des unfugs - vielleicht sieht jemand nen hinweis wo ich keinen sehe …

#
# An unexpected error has been detected by Java Runtime Environment:
#
#  EXCEPTION_ACCESS_VIOLATION (0xc0000005) at pc=0x67d061ff, pid=2244, tid=752
#
# Java VM: Java HotSpot(TM) Client VM (10.0-b19 mixed mode windows-x86)
# Problematic frame:
# C  [pljava.dll+0x61ff]
#
# If you would like to submit a bug report, please visit:
#   http://java.sun.com/webapps/bugreport/crash.jsp
# The crash happened outside the Java Virtual Machine in native code.
# See problematic frame for where to report the bug.
#

---------------  T H R E A D  ---------------

Current thread (0x003f6000):  JavaThread "main" [_thread_in_native, id=752, stack(0x007e0000,0x00be0000)]

siginfo: ExceptionCode=0xc0000005, reading address 0x00000010

Registers:
EAX=0x00000000, EBX=0x003f60f4, ECX=0x003f60f4, EDX=0x003f68b4
ESP=0x00bdf700, EBP=0x00bdf718, ESI=0x0b6b4c60, EDI=0x003f6000
EIP=0x67d061ff, EFLAGS=0x00010206

Top of Stack: (sp=0x00bdf700)
0x00bdf700:   00000001 003f6000 003f5dd8 003f68a0
0x00bdf710:   003f68b4 0b6b4c60 00bdf788 67d0a278
0x00bdf720:   003f60f4 003f6000 6d9344a2 00bdf79c
0x00bdf730:   6d9344aa 00bdf79c 047ddee1 00000000
0x00bdf740:   00000000 00bdf7bc 6d935c63 003f6000
0x00bdf750:   0b6b4c60 00bdf79c 003f6000 6d935c96
0x00bdf760:   003f6000 6d9343d5 003f6000 00000006
0x00bdf770:   00000008 003f6000 0b6b4c60 0b6b4c60 

Instructions: (pc=0x67d061ff)
0x67d061ef:   00 55 89 e5 53 83 ec 14 a1 20 bb d1 67 8b 5d 08
0x67d061ff:   80 78 10 00 74 2f 89 1c 24 e8 73 ff ff ff c7 04 


Stack: [0x007e0000,0x00be0000],  sp=0x00bdf700,  free space=4093k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C  [pljava.dll+0x61ff]
C  [pljava.dll+0xa278]
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::StubRoutines (1)

Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::Interpreter
v  ~BufferBlob::StubRoutines (1)

---------------  P R O C E S S  ---------------

Java Threads: ( => current thread )
  0x0fc52c00 JavaThread "JDWP Command Reader" daemon [_thread_in_native, id=3824, stack(0x11830000,0x11c30000)]
  0x0699bc00 JavaThread "Low Memory Detector" daemon [_thread_blocked, id=1936, stack(0x10c30000,0x11030000)]
  0x06991400 JavaThread "CompilerThread0" daemon [_thread_blocked, id=2764, stack(0x10830000,0x10c30000)]
  0x06986400 JavaThread "JDWP Event Helper Thread" daemon [_thread_blocked, id=3240, stack(0x10430000,0x10830000)]
  0x06983800 JavaThread "JDWP Transport Listener: dt_socket" daemon [_thread_blocked, id=3644, stack(0x10030000,0x10430000)]
  0x06978800 JavaThread "Attach Listener" daemon [_thread_blocked, id=2416, stack(0x0f840000,0x0fc40000)]
  0x06969400 JavaThread "Finalizer" daemon [_thread_blocked, id=2736, stack(0x0f440000,0x0f840000)]
  0x06965000 JavaThread "Reference Handler" daemon [_thread_blocked, id=2548, stack(0x06df0000,0x071f0000)]
=>0x003f6000 JavaThread "main" [_thread_in_native, id=752, stack(0x007e0000,0x00be0000)]

Other Threads:
  0x06962000 VMThread [stack: 0x069f0000,0x06df0000] [id=2900]
  0x0699d000 WatcherThread [stack: 0x11030000,0x11430000] [id=1228]

VM state:not at safepoint (normal execution)

VM Mutex/Monitor currently owned by a thread: None

Heap
 def new generation   total 960K, used 725K [0x07440000, 0x07540000, 0x07920000)
  eden space 896K,  73% used [0x07440000, 0x074e5550, 0x07520000)
  from space 64K, 100% used [0x07520000, 0x07530000, 0x07530000)
  to   space 64K,   0% used [0x07530000, 0x07530000, 0x07540000)
 tenured generation   total 4096K, used 671K [0x07920000, 0x07d20000, 0x0b440000)
   the space 4096K,  16% used [0x07920000, 0x079c7ee8, 0x079c8000, 0x07d20000)
 compacting perm gen  total 12288K, used 4650K [0x0b440000, 0x0c040000, 0x0f440000)
   the space 12288K,  37% used [0x0b440000, 0x0b8cab80, 0x0b8cac00, 0x0c040000)
No shared spaces configured.

Dynamic libraries:
0x00400000 - 0x007db000     C:\Programme\PostgreSQL\8.3\bin\postgres.exe
0x7c920000 - 0x7c9e6000     C:\WINDOWS\system32\ntdll.dll
0x7c800000 - 0x7c915000     C:\WINDOWS\system32\kernel32.dll
0x10000000 - 0x10030000     C:\Programme\PostgreSQL\8.3\bin\SSLEAY32.dll
0x00230000 - 0x00331000     C:\Programme\PostgreSQL\8.3\bin\LIBEAY32.dll
0x719c0000 - 0x719ca000     C:\WINDOWS\system32\WSOCK32.dll
0x71a10000 - 0x71a27000     C:\WINDOWS\system32\WS2_32.dll
0x77b70000 - 0x77bca000     C:\WINDOWS\system32\msvcrt.dll
0x71a00000 - 0x71a08000     C:\WINDOWS\system32\WS2HELP.dll
0x77f30000 - 0x77fdb000     C:\WINDOWS\system32\ADVAPI32.dll
0x77c20000 - 0x77cbf000     C:\WINDOWS\system32\RPCRT4.dll
0x76e40000 - 0x76e53000     C:\WINDOWS\system32\Secur32.dll
0x77bd0000 - 0x77c18000     C:\WINDOWS\system32\GDI32.dll
0x77e20000 - 0x77eb2000     C:\WINDOWS\system32\USER32.dll
0x7c340000 - 0x7c396000     C:\Programme\PostgreSQL\8.3\bin\MSVCR71.dll
0x60e40000 - 0x60e5d000     C:\Programme\PostgreSQL\8.3\bin\libintl3.dll
0x00be0000 - 0x00cc0000     C:\Programme\PostgreSQL\8.3\bin\libiconv2.dll
0x774f0000 - 0x77629000     C:\WINDOWS\system32\OLE32.dll
0x1c000000 - 0x1c093000     C:\Programme\PostgreSQL\8.3\bin\krb5_32.dll
0x00340000 - 0x00347000     C:\Programme\PostgreSQL\8.3\bin\comerr32.dll
0x00350000 - 0x00358000     C:\Programme\PostgreSQL\8.3\bin\k5sprt32.dll
0x00360000 - 0x00382000     C:\Programme\PostgreSQL\8.3\bin\gssapi32.dll
0x00cc0000 - 0x00dae000     C:\Programme\PostgreSQL\8.3\bin\libxml2.dll
0x00db0000 - 0x00e89000     C:\Programme\PostgreSQL\8.3\bin\iconv.dll
0x00390000 - 0x003a3000     C:\Programme\PostgreSQL\8.3\bin\zlib1.dll
0x76e00000 - 0x76e2f000     C:\WINDOWS\system32\WLDAP32.dll
0x78130000 - 0x781cb000     C:\WINDOWS\WinSxS\x86_Microsoft.VC80.CRT_1fc8b3b9a1e18e3b_8.0.50727.762_x-ww_6B128700\MSVCR80.dll
0x76180000 - 0x7619d000     C:\WINDOWS\system32\IMM32.DLL
0x71930000 - 0x71972000     C:\WINDOWS\system32\mswsock.dll
0x073e0000 - 0x0743b000     C:\WINDOWS\system32\hnetcfg.dll
0x718f0000 - 0x718f8000     C:\WINDOWS\System32\wshtcpip.dll
0x01b70000 - 0x01b7a000     C:\Programme\PostgreSQL\8.3\lib\plugins\plugin_debugger.dll
0x67d00000 - 0x67ec6000     C:\Programme\PostgreSQL\8.3\lib\pljava.dll
0x6d870000 - 0x6dac0000     C:\Programme\Java\jdk1.6.0_04\jre\bin\client\jvm.dll
0x76990000 - 0x769be000     C:\WINDOWS\system32\WINMM.dll
0x6bd00000 - 0x6bd0d000     C:\WINDOWS\system32\SYNCOR11.DLL
0x6d320000 - 0x6d328000     C:\Programme\Java\jdk1.6.0_04\jre\bin\hpi.dll
0x76a60000 - 0x76a6b000     C:\WINDOWS\system32\PSAPI.DLL
0x6d410000 - 0x6d439000     C:\Programme\Java\jdk1.6.0_04\jre\bin\jdwp.dll
0x6d770000 - 0x6d776000     C:\Programme\Java\jdk1.6.0_04\jre\bin\npt.dll
0x6d820000 - 0x6d82c000     C:\Programme\Java\jdk1.6.0_04\jre\bin\verify.dll
0x6d3c0000 - 0x6d3df000     C:\Programme\Java\jdk1.6.0_04\jre\bin\java.dll
0x6d860000 - 0x6d86f000     C:\Programme\Java\jdk1.6.0_04\jre\bin\zip.dll
0x6d290000 - 0x6d297000     C:\Programme\Java\jdk1.6.0_04\jre\bin\dt_socket.dll

VM Arguments:
jvm_args: -agentlib:jdwp=transport=dt_socket,server=y,address=8444,suspend=n -Dsqlj.defaultconnection=jdbc:default:connection vfprintf -Xrs 
java_command: <unknown>
Launcher Type: generic

Environment Variables:
....
PROCESSOR_IDENTIFIER=x86 Family 15 Model 3 Stepping 4, GenuineIntel



---------------  S Y S T E M  ---------------

OS: Windows Server 2003 family Build 3790 Service Pack 2

CPU:total 1 (1 cores per cpu, 1 threads per core) family 15 model 3 stepping 4, cmov, cx8, fxsr, mmx, sse, sse2, sse3

Memory: 4k page, physical 1564128k(672808k free), swap 3515908k(2569252k free)

vm_info: Java HotSpot(TM) Client VM (10.0-b19) for windows-x86 JRE (1.6.0_04-b12), built on Dec 14 2007 00:51:20 by "java_re" with MS VC++ 7.1

time: Thu Aug 28 16:03:51 2008
elapsed time: 14 seconds

ich hab mal ein bisserl in dem code geschnueffelt … mir scheint die TransactionListener Geschichte ist noch nicht sonderlich alt …

da es sich hierbei um ne call-back funktionalitaet handelt hab ich mal geschaut wie “uebliche” funktionen aufgerufen werden … da wird a weng schnickschnack vorher erledigt, der bei dem callback voellig fehlt … also der part wo dann jni aufrufe getaetigt werden … da kommt zwar der aufruf in der VM an - aber dort darf man “nix anfassen” weil sonst alles karpott geht

muss ich mich jetzt auch noch mit C code rumschlagen :slight_smile:

sieht so aus, dass hier der SPI context nicht richtig initialisiert ist und so Schmankerl …

schade …

also ich habe mal aufgrund meiner vermutungen ein bisschen experimentiert …

dazu habe ich einen thread aus dem context der normalen PL/java funktion erzeugt, bei der die aufrufe bekannter massen funktionieren … dieser thread wartet halt auf einen mutex …

in dem TransactionListener mach ich nichts weiter als den mutext / thread anzuschupsen mit einem simplen notify (was gluecklicher weise zu keinen problemen fuehrt) …

der obige thread darf dann zumindest mit den objekten aus seinem context arbeiten - ohne dass die VM zusammenfaellt …

der fehler trat/tritt immer bei irgendwelchen aufrufen in der pljava lib (bei mir dll) auf … was wohl daran liegt, dass der thread/process welcher den callback aufruft nicht mit dem thread, dem das daten-segment der callback-routine synchronisiert wird - also zugriff auf datensegment aus falschem thread-context … oder irgendwelche strukturen in der dll vor diesem aufruf nicht richtig initialisiert … die ACCESS_VIOLATION laesst darauf schliessen …

vielleicht haengt das ja auch mit modernem speicherschutz zusammen, es wundert mich naemlich ein bisschen, dass dem entwickler das nicht aufgefallen ist - weil man wirklich fast nichts in der callback-routine machen kann ohne dass man die VM zugrunde richtet