Bug: JDBC probe calls getMetadata() on a closed connection

Questions about YourKit Java Profiler
Post Reply
bcalmac
Posts: 15
Joined: Tue Apr 29, 2008 6:15 pm

Bug: JDBC probe calls getMetadata() on a closed connection

Post by bcalmac »

When I run my application with profiling enabled I get the exception below. You ca see the sequence Connection.close() -> YourKit -> Connection.getMetadata()

Code: Select all

2016-05-02 14:26:47.092 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
org.h2.jdbc.JdbcSQLException: The object is already closed [90007-172]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:329) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:169) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:146) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:135) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.checkClosed(JdbcXAConnection.java:488) [h2-1.3.172.jar:1.3.172]
	at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1388) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.jdbc.JdbcConnection.getMetaData(JdbcConnection.java:309) ~[h2-1.3.172.jar:1.3.172]
	at com.yourkit.runtime.Callback.callObjectMethod0(Native Method) [na:na]
	at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:72) [na:na]
	at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:117) [na:na]
	at com.yourkit.probes.builtin.Databases.getConnectionURL(Databases.java:729) [na:na]
	at com.yourkit.probes.builtin.DatabasesLW$1.getResourceName(DatabasesLW.java:50) [na:na]
	at com.yourkit.probes.ResourceCounter.close(ResourceCounter.java:242) [na:na]
	at com.yourkit.probes.builtin.DatabasesLW$Connection_or_Statement_close_Probe.onExit(DatabasesLW.java:275) [na:na]
	at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.close(JdbcXAConnection.java:478) [h2-1.3.172.jar:1.3.172]
	at com.synapsense.NoAutocommitQueryRunner.batch(NoAutocommitQueryRunner.java:31) [dm-utils-6.8.0.jar:na]
The version I have is 2016.02-b35.
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by Anton Katilin »

Hi,

This is a new issue. It must be H2 specific. Could you please provide the profiler agent log file ~/.yjp/log/<session name>-<pid>.log

Anyway, since we likely understand how to fix this problem, we can offer you the agent with a fix for testing. On which platform (OS, bitness) do you run the profiled application?

Best regards,
Anton
bcalmac
Posts: 15
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by bcalmac »

I use Windows x64.

I'll include a few YJP logs in individual messages.
bcalmac
Posts: 15
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by bcalmac »

It looks like posting is throttled. Here's one of the logs:

Code: Select all

16.02-35 0.016: Command line:
  C:\tools\yjp\jre64\bin\javaw.exe
  -XX:+HeapDumpOnOutOfMemoryError
  -Xmx4G
  -XX:PermSize=256m
  -XX:MaxPermSize=256m
  -jar
  ..\lib\yjp.jar
16.02-35 0.016: Executable: C:\tools\yjp\jre64\bin\javaw.exe
16.02-35 0.016: Windows 7; version 6.1.7601; 64-bit process
16.02-35 0.017: hid: 16022D45VV245481W6916ZW0VX03V680992XY094YU 64-bit machine
16.02-35 0.017: Today is 20160502
16.02-35 0.017: full_build_stamp: 2016.02.35 201604221705
16.02-35 0.017: Agent library path: C:\tools\yjp\bin\win64\yjpagent.dll
16.02-35 0.017: 
---------------------------------------------------------------------
Product: YourKit Java Profiler 2016.02-b35 - built on 201604221705
JDK: 1.8.0_77
VM: Java HotSpot(TM) 64-Bit Server VM
Vendor: Oracle Corporation
OS: Windows 7
OS version: 6.1
OS arch: amd64
Date and time: Mon May 02 12:53:12 PDT 2016
Properties:
  awt.toolkit=sun.awt.windows.WToolkit
  file.encoding.pkg=sun.io
  file.encoding=Cp1252
  file.separator=\
  java.awt.graphicsenv=sun.awt.Win32GraphicsEnvironment
  java.awt.printerjob=sun.awt.windows.WPrinterJob
  java.class.path=..\lib\yjp.jar
  java.class.version=52.0
  java.endorsed.dirs=C:\tools\yjp\jre64\lib\endorsed
  java.ext.dirs=C:\tools\yjp\jre64\lib\ext;C:\Windows\Sun\Java\lib\ext
  java.home=C:\tools\yjp\jre64
  java.io.tmpdir=C:\Users\bca\AppData\Local\Temp\
  java.library.path=C:\tools\yjp\jre64\bin;C:\Windows\Sun\Java\bin;C:\Windows\system32;C:\Windows;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\tools\java\bin;C:\tools\scala\bin;C:\tools\maven\bin;C:\tools\ant\bin;C:\tools\gradle\bin;C:\tools\mariadb\bin;C:\tools\rabbitmq\rabbitmq_server-3.6.1\sbin;C:\tools\spring-boot-cli\bin;C:\tools\ruby\bin;C:\tools\sencha;C:\tools\bin;C:\tools\sysinternals;C:\cygwin\bin;C:\src\scripts;C:\Program Files\SourceGear\Common\DiffMerge;C:\Windows\System32\WindowsPowerShell\v1.0;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\;C:\tools\idea\bin;C:\Program Files (x86)\Notepad++;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\;.
  java.runtime.name=Java(TM) SE Runtime Environment
  java.runtime.version=1.8.0_77-b03
  java.specification.name=Java Platform API Specification
  java.specification.vendor=Oracle Corporation
  java.specification.version=1.8
  java.vendor.url.bug=http://bugreport.sun.com/bugreport/
  java.vendor.url=http://java.oracle.com/
  java.vendor=Oracle Corporation
  java.version=1.8.0_77
  java.vm.info=mixed mode
  java.vm.name=Java HotSpot(TM) 64-Bit Server VM
  java.vm.specification.name=Java Virtual Machine Specification
  java.vm.specification.vendor=Oracle Corporation
  java.vm.specification.version=1.8
  java.vm.vendor=Oracle Corporation
  java.vm.version=25.77-b03
  line.separator=


  os.arch=amd64
  os.name=Windows 7
  os.version=6.1
  path.separator=;
  sun.arch.data.model=64
  sun.awt.enableExtraMouseButtons=true
  sun.boot.class.path=C:\tools\yjp\jre64\lib\resources.jar;C:\tools\yjp\jre64\lib\rt.jar;C:\tools\yjp\jre64\lib\sunrsasign.jar;C:\tools\yjp\jre64\lib\jsse.jar;C:\tools\yjp\jre64\lib\jce.jar;C:\tools\yjp\jre64\lib\charsets.jar;C:\tools\yjp\jre64\lib\jfr.jar;C:\tools\yjp\jre64\classes
  sun.boot.library.path=C:\tools\yjp\jre64\bin
  sun.cpu.endian=little
  sun.cpu.isalist=amd64
  sun.desktop=windows
  sun.io.unicode.encoding=UnicodeLittle
  sun.java.command=..\lib\yjp.jar
  sun.java.launcher=SUN_STANDARD
  sun.jnu.encoding=Cp1252
  sun.management.compiler=HotSpot 64-Bit Tiered Compilers
  sun.os.patch.level=Service Pack 1
  user.country=US
  user.dir=C:\tools\yjp\bin
  user.home=C:\Users\bca
  user.language=en
  user.name=bca
  user.script=
  user.timezone=America/Los_Angeles
  user.variant=
Environment:
  ALLUSERSPROFILE=C:\ProgramData
  ANT_HOME=C:\tools\ant
  APPDATA=C:\Users\bca\AppData\Roaming
  CATALINA_HOME=C:\src\sz-80\tomcat
  COMMPath=C:\Program Files\Lenovo\Communications Utility
  COMPUTERNAME=CAS-BCA-W540
  ComSpec=C:\Windows\system32\cmd.exe
  CommonProgramFiles(x86)=C:\Program Files (x86)\Common Files
  CommonProgramFiles=C:\Program Files\Common Files
  CommonProgramW6432=C:\Program Files\Common Files
  ERLANG_HOME=c:\tools\erlang-18.3
  FP_NO_HOST_CHECK=NO
  GRAPHVIZ_DOT=C:\tools\graphviz\bin\dot.exe
  HOMEDRIVE=C:
  HOMEPATH=\Users\bca
  IDEA_JDK_64=c:\tools\java-8
  JAVA_HOME=C:\tools\java
  LOCALAPPDATA=C:\Users\bca\AppData\Local
  LOGONSERVER=\\CAS-AD-DC-01P
  M2_HOME=C:\tools\maven
  NUMBER_OF_PROCESSORS=8
  OS=Windows_NT
  PATHEXT=.COM;.EXE;.BAT;.CMD;.VBS;.VBE;.JS;.JSE;.WSF;.WSH;.MSC
  PROCESSOR_ARCHITECTURE=AMD64
  PROCESSOR_IDENTIFIER=Intel64 Family 6 Model 60 Stepping 3, GenuineIntel
  PROCESSOR_LEVEL=6
  PROCESSOR_REVISION=3c03
  PSModulePath=C:\Windows\system32\WindowsPowerShell\v1.0\Modules\
  PUBLIC=C:\Users\Public
  Path=C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\tools\java\bin;C:\tools\scala\bin;C:\tools\maven\bin;C:\tools\ant\bin;C:\tools\gradle\bin;C:\tools\mariadb\bin;C:\tools\rabbitmq\rabbitmq_server-3.6.1\sbin;C:\tools\spring-boot-cli\bin;C:\tools\ruby\bin;C:\tools\sencha;C:\tools\bin;C:\tools\sysinternals;C:\cygwin\bin;C:\src\scripts;C:\Program Files\SourceGear\Common\DiffMerge;C:\Windows\System32\WindowsPowerShell\v1.0;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\;C:\tools\idea\bin;C:\Program Files (x86)\Notepad++;C:\Program Files\Intel\WiFi\bin\;C:\Program Files\Common Files\Intel\WirelessCommon\
  ProgramData=C:\ProgramData
  ProgramFiles(x86)=C:\Program Files (x86)
  ProgramFiles=C:\Program Files
  ProgramW6432=C:\Program Files
  RABBITMQ_HOME=C:\tools\rabbitmq\rabbitmq_server-3.6.1
  READYAPPS=C:\ProgramData\Lenovo\ReadyApps
  SCALA_HOME=C:\tools\scala
  SESSIONNAME=Console
  SystemDrive=C:
  SystemRoot=C:\Windows
  TEMP=C:\Users\bca\AppData\Local\Temp
  TMP=C:\Users\bca\AppData\Local\Temp
  TVT=C:\Program Files (x86)\Lenovo
  TVTCOMMON=C:\Program Files (x86)\Common Files\Lenovo
  UATDATA=C:\Windows\CCM\UATData\D9F8C395-CAB8-491d-B8AC-179A1FE1BE77
  UOIPME_REG_PATH=C:\Program Files\Intel Corporation\USB over IP
  USERDNSDOMAIN=PANDUIT.COM
  USERDOMAIN=PANDUIT
  USERNAME=bca
  USERPROFILE=C:\Users\bca
  windir=C:\Windows
  windows_tracing_flags=3
---------------------------------------------------------------------


16.02-35 0.017: com.yourkit.Main1: starting...
16.02-35 0.017: com.yourkit.Main1: number of args: 0
16.02-35 0.017: com.yourkit.Main1: offlineOptionSpecified = false
16.02-35 0.027: com.yourkit.i.c1: [update installer]: no update scheduled - nothing to do
16.02-35 0.078: com.yourkit.Main1: oomeDumperStatus: 1
16.02-35 0.148: com.yourkit.i.f.a.a: FYI: native (current) LAF font: javax.swing.plaf.FontUIResource[family=Tahoma,name=Tahoma,style=plain,size=11]
16.02-35 0.148: com.yourkit.i.f.a.a: FYI: metal font: javax.swing.plaf.FontUIResource[family=Dialog,name=Dialog,style=bold,size=12]
16.02-35 0.150: com.yourkit.i.f.a.a: general font: javax.swing.plaf.FontUIResource[family=Segoe UI,name=Segoe UI,style=plain,size=12]
16.02-35 0.150: com.yourkit.i.f.a.a: menu font: javax.swing.plaf.FontUIResource[family=Segoe UI,name=Segoe UI,style=plain,size=12]
16.02-35 0.443: com.yourkit.i.i.c.c: ParallelExecutor: pool size 8
16.02-35 0.520: shmem: Global\YOURKIT SHARE G: OK, isFirst=1
16.02-35 0.521: shmem: Local\YOURKIT SHARE L: OK, isFirst=1
16.02-35 0.524: shmem: Global\YOURKIT SHARE2 G: OK, isFirst=0
16.02-35 0.524: shmem: Local\YOURKIT SHARE2 L: OK, isFirst=1
16.02-35 0.530: shmem: Global\YOURKIT SHARE5 G: OK, isFirst=0
16.02-35 0.530: shmem: Local\YOURKIT SHARE5 L: OK, isFirst=1
16.02-35 0.720: com.yourkit.i.b6: marker: created C:\Users\bca\.yjp\.yjp_20071015_ui60834
16.02-35 1.067: com.yourkit.i.q: UPDATES_URL: https://www.yourkit.com/updates_yjp_2016_02.xml?build=2016.02.35
16.02-35 2.153: com.yourkit.k.g: LWS-update: code=200 text: payload=AM...   result=ok 
16.02-35 18.023: com.yourkit.d.bc: exiting now...
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by Anton Katilin »

Could you please download this agent library file

https://www.yourkit.com/download/tmp/20 ... pagent.dll

...and write it over the existing agent which, according to the log, should be C:\tools\yjp\bin\win64\yjpagent.dll
bcalmac
Posts: 15
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by bcalmac »

The new build doesn't fix the problem. I still get the same exception when enabling the profiler (everything's fine without it).

Furthermore, this new build doesn't generate a logfile under .yjp/log.
bcalmac
Posts: 15
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by bcalmac »

Here's the stacktrace, in case you expect some change there:

Code: Select all

2016-05-03 10:30:10.784 PDT [main] ERROR h2database - logstore:jdbc[3] exception
org.h2.jdbc.JdbcSQLException: The object is already closed [90007-172]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:329) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:169) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:146) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:135) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.checkClosed(JdbcXAConnection.java:488) [h2-1.3.172.jar:1.3.172]
	at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1388) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.jdbc.JdbcConnection.getMetaData(JdbcConnection.java:309) ~[h2-1.3.172.jar:1.3.172]
	at com.yourkit.runtime.Callback.callObjectMethod0(Native Method) [na:na]
	at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:72) [na:na]
	at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:117) [na:na]
	at com.yourkit.probes.builtin.Databases.getConnectionURL(Databases.java:729) [na:na]
	at com.yourkit.probes.builtin.DatabasesLW$1.getResourceName(DatabasesLW.java:50) [na:na]
	at com.yourkit.probes.ResourceCounter.getResourceNameSafe(ResourceCounter.java:258) [na:na]
	at com.yourkit.probes.ResourceCounter.close(ResourceCounter.java:242) [na:na]
	at com.yourkit.probes.builtin.DatabasesLW$Connection_or_Statement_close_Probe.onExit(DatabasesLW.java:275) [na:na]
	at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.close(JdbcXAConnection.java:478) [h2-1.3.172.jar:1.3.172]
	at com.synapsense.NoAutocommitQueryRunner.batch(NoAutocommitQueryRunner.java:31) [dm-utils-6.8.0.jar:na]
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by Anton Katilin »

Thanks for testing.

Regarding the log file. It's absence is absolutely strange. Are you sure you're looking for .yjp/log in appropriate user home? Anyway, you can explicitly specify the log file location with the startup option "logdir":
https://www.yourkit.com/docs/java/help/ ... ptions.jsp

Regarding the exception itself. Where do you see that exception, in what log file? Even if it is thrown, it must not go beyond the probe's code in the new agent. In other words, It must not be an uncaught exception now.
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by Anton Katilin »

By the way, please note the log you've send earlier is not the profiled application's log, but the profiler UI's log.
bcalmac
Posts: 15
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by bcalmac »

Oh, OK. It looks like the most recent log I have is from 2016.02.34.

Code: Select all

16.02-34 0.001: Command line:
  C:\src\ss-selene\middle\runtime\SynapDM\SynapDM.exe
16.02-34 0.001: Executable: C:\src\ss-selene\middle\runtime\SynapDM\SynapDM.exe
16.02-34 0.001: Windows 7; version 6.1.7601; 64-bit process
16.02-34 0.002: hid: 16022D45VV245481W6916ZW0VX03V680992XY094YU 64-bit machine
16.02-34 0.002: Today is 20160422
16.02-34 0.002: full_build_stamp: 2016.02.34 201604051221
16.02-34 0.002: Agent library path: C:\tools\yjp\bin\win64\yjpagent.dll
16.02-34 0.002: Agent_OnLoad: orig_options=dir=.
  full_options=dir=.
16.02-34 0.002: phase: 1
16.02-34 0.002: jvmtiVersion: 30010201
16.02-34 0.002: vendor: Oracle Corporation
16.02-34 0.002: version: 24.79-b02
16.02-34 0.002: info: mixed mode, sharing
16.02-34 0.002: isJava6: 0
16.02-34 0.003: session_id: 34893775676203 (1461363499,8124)
16.02-34 0.004: line_method: 1
16.02-34 0.011: Reusing existing jar file: C:\cygwin\tmp\yjp201604051221.jar
16.02-34 0.012: JVMTI 30010201; 24.79-b02; Oracle Corporation; mixed mode, sharing
16.02-34 0.099: Successfully registered probes: 26
  Registered: .AWTEvents
  Registered: .AgentLoadingSupport
  Registered: .AsyncChannels
  Registered: .Cassandra
  Registered: .CassandraLW
  Registered: .Databases
  Registered: .DatabasesLW
  Registered: .Files
  Registered: .FilesLW
  Registered: .HBase
  Registered: .HBaseLW
  Registered: .JNDI
  Registered: .JPA_DataNucleus
  Registered: .JPA_EclipseLink
  Registered: .JPA_Hibernate
  Registered: .JPA_OpenJPA
  Registered: .JUnitTests
  Registered: .MongoDB
  Registered: .MongoDBLW
  Registered: .Processes
  Registered: .Servlets
  Registered: .ServletsLW
  Registered: .Sockets
  Registered: .SocketsLW
  Registered: .TestNG
  Registered: .Threads
Would it be useful for you to run the same test on b34?
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by Anton Katilin »

You may try running with b34, but we would prefer the log created with the latest build with the proposed fix.

Also, it seems you paste truncated logs. We need full logs. If you cannot share it here in the forum, please feel free to send the files attached to [email protected]

Could you please answer this question:
Where do you see that exception, in what log file? Even if it is thrown, it must not go beyond the probe's code in the new agent. In other words, It must not be an uncaught exception now.
bcalmac
Posts: 15
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by bcalmac »

To make sure I run the right patch: The file that I downloaded has 2,750,976 bytes. The old file (build 35) that I renamed to yjpagent.old.dll has 2,748,416 bytes. Does this match your numbers?

See two samples of the exception below. The exception is logged by H2, so it may show up even if you catch it.

Code: Select all

2016-05-03 10:30:10.784 PDT [main] ERROR h2database - logstore:jdbc[3] exception
org.h2.jdbc.JdbcSQLException: The object is already closed [90007-172]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:329) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:169) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:146) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:135) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.checkClosed(JdbcXAConnection.java:488) [h2-1.3.172.jar:1.3.172]
	at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1388) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.jdbc.JdbcConnection.getMetaData(JdbcConnection.java:309) ~[h2-1.3.172.jar:1.3.172]
	at com.yourkit.runtime.Callback.callObjectMethod0(Native Method) [na:na]
	at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:72) [na:na]
	at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:117) [na:na]
	at com.yourkit.probes.builtin.Databases.getConnectionURL(Databases.java:729) [na:na]
	at com.yourkit.probes.builtin.DatabasesLW$1.getResourceName(DatabasesLW.java:50) [na:na]
	at com.yourkit.probes.ResourceCounter.getResourceNameSafe(ResourceCounter.java:258) [na:na]
	at com.yourkit.probes.ResourceCounter.close(ResourceCounter.java:242) [na:na]
	at com.yourkit.probes.builtin.DatabasesLW$Connection_or_Statement_close_Probe.onExit(DatabasesLW.java:275) [na:na]
	at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.close(JdbcXAConnection.java:478) [h2-1.3.172.jar:1.3.172]
	at com.synapsense.NoAutocommitQueryRunner.batch(NoAutocommitQueryRunner.java:31) [dm-utils-6.8.0.jar:na]
	at com.synapsense.logback.db.H2EventRepository.saveEvents(H2EventRepository.java:59) [dm-logging-6.8.0.jar:na]
	at com.synapsense.logback.LoggingEventStore.process(LoggingEventStore.java:60) [dm-logging-6.8.0.jar:na]
	at com.synapsense.eventflow.backup.PrimarySwitch.process(PrimarySwitch.java:44) [dm-utils-6.8.0.jar:na]
	at com.synapsense.eventflow.backup.BackupFlowSwitcher.process(BackupFlowSwitcher.java:30) [dm-utils-6.8.0.jar:na]
	at com.synapsense.logback.ESAppender.append(ESAppender.java:102) [dm-logging-6.8.0.jar:na]
	at com.synapsense.logback.ESAppender.append(ESAppender.java:30) [dm-logging-6.8.0.jar:na]
	at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) [logback-core-1.0.13.jar:na]
	at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:48) [logback-core-1.0.13.jar:na]
	at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272) [logback-classic-1.0.13.jar:na]
	at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259) [logback-classic-1.0.13.jar:na]
	at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:441) [logback-classic-1.0.13.jar:na]
	at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:395) [logback-classic-1.0.13.jar:na]
	at ch.qos.logback.classic.Logger.log(Logger.java:787) [logback-classic-1.0.13.jar:na]
	at org.apache.log4j.Category.differentiatedLog(Category.java:186) [log4j-over-slf4j-1.7.5.jar:1.7.5]
	at org.apache.log4j.Category.info(Category.java:229) [log4j-over-slf4j-1.7.5.jar:1.7.5]
	at com.synapsense.plugin.simulator.SimulatorPlugin.loadConfFile(SimulatorPlugin.java:166) [dm-simulator-plugin-6.8.0.jar:na]
	at com.synapsense.plugin.simulator.SimulatorPlugin.<init>(SimulatorPlugin.java:50) [dm-simulator-plugin-6.8.0.jar:na]
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [na:1.7.0_79]
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57) [na:1.7.0_79]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [na:1.7.0_79]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:526) [na:1.7.0_79]
	at java.lang.Class.newInstance(Class.java:379) [na:1.7.0_79]
	at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:373) [na:1.7.0_79]
	at java.util.ServiceLoader$1.next(ServiceLoader.java:445) [na:1.7.0_79]
	at com.synapsense.plugin.manager.DeviceManagerCore.loadPlugins(DeviceManagerCore.java:48) [dm-core-6.8.0.jar:na]
	at com.synapsense.plugin.manager.DeviceManagerCore.<init>(DeviceManagerCore.java:36) [dm-core-6.8.0.jar:na]
	at com.synapsense.plugin.manager.DeviceManagerCore.<clinit>(DeviceManagerCore.java:26) [dm-core-6.8.0.jar:na]
	at com.synapsense.plugin.Launcher.main(Launcher.java:51) [dm-core-6.8.0.jar:na]

Code: Select all

2016-05-03 10:30:18.773 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
org.h2.jdbc.JdbcSQLException: The object is already closed [90007-172]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:329) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:169) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:146) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.message.DbException.get(DbException.java:135) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.checkClosed(JdbcXAConnection.java:488) [h2-1.3.172.jar:1.3.172]
	at org.h2.jdbc.JdbcConnection.checkClosed(JdbcConnection.java:1388) ~[h2-1.3.172.jar:1.3.172]
	at org.h2.jdbc.JdbcConnection.getMetaData(JdbcConnection.java:309) ~[h2-1.3.172.jar:1.3.172]
	at com.yourkit.runtime.Callback.callObjectMethod0(Native Method) [na:na]
	at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:72) [na:na]
	at com.yourkit.probes.ReflectionUtil.callMethod0(ReflectionUtil.java:117) [na:na]
	at com.yourkit.probes.builtin.Databases.getConnectionURL(Databases.java:729) [na:na]
	at com.yourkit.probes.builtin.DatabasesLW$1.getResourceName(DatabasesLW.java:50) [na:na]
	at com.yourkit.probes.ResourceCounter.getResourceNameSafe(ResourceCounter.java:258) [na:na]
	at com.yourkit.probes.ResourceCounter.close(ResourceCounter.java:242) [na:na]
	at com.yourkit.probes.builtin.DatabasesLW$Connection_or_Statement_close_Probe.onExit(DatabasesLW.java:275) [na:na]
	at org.h2.jdbcx.JdbcXAConnection$PooledJdbcConnection.close(JdbcXAConnection.java:478) [h2-1.3.172.jar:1.3.172]
	at com.synapsense.NoAutocommitQueryRunner.batch(NoAutocommitQueryRunner.java:31) [dm-utils-6.8.0.jar:na]
	at com.synapsense.plugin.transport.db.H2DataRepository.saveDataPoints(H2DataRepository.java:76) [dm-es-transport-6.8.0.jar:na]
	at com.synapsense.plugin.transport.jms.DataEventStore.process(DataEventStore.java:52) [dm-es-transport-6.8.0.jar:na]
	at com.synapsense.eventflow.backup.PrimarySwitch.process(PrimarySwitch.java:44) [dm-utils-6.8.0.jar:na]
	at com.synapsense.eventflow.backup.BackupFlowSwitcher.process(BackupFlowSwitcher.java:30) [dm-utils-6.8.0.jar:na]
	at com.synapsense.plugin.transport.jms.JMSTransport.sendData(JMSTransport.java:217) [dm-es-transport-6.8.0.jar:na]
	at com.synapsense.plugin.manager.CompositeTransport.sendData(CompositeTransport.java:104) [dm-core-6.8.0.jar:na]
	at com.synapsense.plugin.simulator.sensorplace.SensorsStore.sendValue(SensorsStore.java:120) [dm-simulator-plugin-6.8.0.jar:na]
	at com.synapsense.plugin.simulator.sensorplace.SensorImitator.run(SensorImitator.java:133) [dm-simulator-plugin-6.8.0.jar:na]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) [na:1.7.0_79]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304) [na:1.7.0_79]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178) [na:1.7.0_79]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.7.0_79]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_79]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_79]
	at java.lang.Thread.run(Thread.java:745) [na:1.7.0_79]
But something is still messed up. The behavior with the profiler enabled is different. H2 will keep trying to close that original connection on any later activity and fail every time. This is just a grep for the first line of the exception:

Code: Select all

	1854	2016-05-03 10:30:10.784 PDT [main] ERROR h2database - logstore:jdbc[3] exception
	1945	2016-05-03 10:30:11.760 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
	1979	2016-05-03 10:30:11.929 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
	2013	2016-05-03 10:30:12.218 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
	2064	2016-05-03 10:30:12.810 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
	2098	2016-05-03 10:30:13.410 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
	2145	2016-05-03 10:30:14.005 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
	2179	2016-05-03 10:30:14.900 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
	2213	2016-05-03 10:30:15.794 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
	2247	2016-05-03 10:30:16.986 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
	2281	2016-05-03 10:30:17.880 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
	2336	2016-05-03 10:30:18.773 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
	2370	2016-05-03 10:30:19.376 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
	2404	2016-05-03 10:30:19.966 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
	2438	2016-05-03 10:30:20.867 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
	2472	2016-05-03 10:30:22.052 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
	2506	2016-05-03 10:30:22.943 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
	2540	2016-05-03 10:30:23.839 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
	2574	2016-05-03 10:30:25.034 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
	2608	2016-05-03 10:30:25.918 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
	2642	2016-05-03 10:30:26.224 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
	2676	2016-05-03 10:30:26.819 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
	2710	2016-05-03 10:30:28.011 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
	2744	2016-05-03 10:30:28.310 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
	2778	2016-05-03 10:30:28.905 PDT [pool-1-thread-3] ERROR h2database - logstore:jdbc[4] exception
	2812	2016-05-03 10:30:29.205 PDT [pool-1-thread-4] ERROR h2database - logstore:jdbc[4] exception
	2846	2016-05-03 10:30:29.800 PDT [pool-1-thread-1] ERROR h2database - logstore:jdbc[4] exception
	2880	2016-05-03 10:30:30.695 PDT [pool-1-thread-2] ERROR h2database - logstore:jdbc[4] exception
Instead of catching the exception, can you instead check that the connection is not already closed? This would make YJP more transparent. Who knows what funky stuff the H2 connection pool does when closing a connection? Maybe it also tries closing connections that failed earlier. All exception above refer to the same connection, identified as [90007-172].

Finally, why do I no longer see the yjp log files after the b35 upgrade? Can I look for them in some other place?
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by Anton Katilin »

Yes, you were running the right patch.
The exception is logged by H2, so it may show up even if you catch it.
OK.
Instead of catching the exception, can you instead check that the connection is not already closed?
We've improved the fix according to this approach. Could you please try the latest agent:
https://www.yourkit.com/download/tmp/20 ... pagent.dll
The size should be 2,615,296.
Finally, why do I no longer see the yjp log files after the b35 upgrade? Can I look for them in some other place?
I don't know what happened. There were no changes between b34 and b35 in regard of the log file processing. We do not see any log file issues with the newest builds.

Perhaps something has changed on your system. For example, you use cygwin. If it redefines the user home variables used by Java, please take a look at cygwin's user home instead of the normal Windows user home (or vise versa).

Anyway, since you get the logs with "logdir" specified (you do, right?), the problem is not with the agent's inability to create the log but rather with the detected user home directory where it should be located.

If the agent cannot create the log, it writes an error message to stdout or stderr (sorry, don't remember the exact stream). Please check the application logs for such messages.
bcalmac
Posts: 15
Joined: Tue Apr 29, 2008 6:15 pm

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by bcalmac »

Looks good now, thank you!

I'll track down the log problem some other time, now I'm anxious to get back to work.
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Bug: JDBC probe calls getMetadata() on a closed connecti

Post by Anton Katilin »

Thank you for testing. The next build 36 will contain the fix.
Post Reply