Add stack trace print for jlm test connect exceptions

[lumpfish]

Signed-off-by: Simon Rushton srushton@redhat.com

[lumpfish]

Fixes #402

[lumpfish]

Test run here: #402

The test did hit an occurrence of the exception which was being reported simply as Exiting as JVM we are connected to has finished.

The output from this PR now gives full information about the exception:

11:08:28  STF 11:08:28.432 - +------ Step 5 - Wait for the processes to complete
11:08:28  STF 11:08:28.432 - | Wait for processes to meet expectations
11:08:28  STF 11:08:28.432 - |   Processes: [LT1, CL1]
11:08:28  STF 11:08:28.432 - |
11:08:28  STF 11:08:28.432 - Monitoring processes: CL1 LT1
11:08:29  CL1 j> 2021/02/04 11:08:29.110 ServerURL=service:jmx:rmi:///jndi/rmi://localhost:1234/jmxrmi
11:08:29  CL1 j> 2021/02/04 11:08:29.412 Attempting to connect

11:08:30  CL1 j> 2021/02/04 11:08:30.024 Monitored VM not ready at Feb 4, 2021, 11:08:30 AM (attempt 1, elapsed 532ms).
11:08:30  CL1 j> 2021/02/04 11:08:30.025 Waiting 5 secs and trying again...

11:08:35  CL1 j> 2021/02/04 11:08:35.025 Attempting to connect

11:08:37  CL1 j> 2021/02/04 11:08:37.355 Connection established!
11:08:37  CL1 j> 2021/02/04 11:08:37.624 Starting to write data

11:08:39  CL1 j> 2021/02/04 11:08:38.318 Exiting as UnmarshalException thrown receiving data from the connected JVM.  This may mean the JVM we are connected to has finished. null
11:08:39  CL1 stderr java.lang.reflect.UndeclaredThrowableException
11:08:39  CL1 stderr 	at jdk.proxy1/jdk.proxy1.$Proxy0.getSystemProperties(Unknown Source)
11:08:39  CL1 stderr 	at net.adoptopenjdk.test.jlm.resources.EnvironmentData.writeData(EnvironmentData.java:120)
11:08:39  CL1 stderr 	at net.adoptopenjdk.test.jlm.remote.ThreadProfiler.getStatsViaProxy(ThreadProfiler.java:128)
11:08:39  CL1 stderr 	at net.adoptopenjdk.test.jlm.remote.ThreadProfiler.main(ThreadProfiler.java:97)
11:08:39  CL1 stderr Caused by: java.rmi.UnmarshalException: error unmarshalling return; nested exception is: 
11:08:39  CL1 stderr 	javax.net.ssl.SSLException: Tag mismatch!
11:08:39  CL1 stderr 	at java.rmi/sun.rmi.server.UnicastRef.invoke(UnicastRef.java:197)
11:08:39  CL1 stderr 	at jdk.remoteref/jdk.jmx.remote.internal.rmi.PRef.invoke(Unknown Source)
11:08:39  CL1 stderr 	at java.management.rmi/javax.management.remote.rmi.RMIConnectionImpl_Stub.getAttribute(RMIConnectionImpl_Stub.java:279)
11:08:39  CL1 stderr 	at java.management.rmi/javax.management.remote.rmi.RMIConnector$RemoteMBeanServerConnection.getAttribute(RMIConnector.java:904)
11:08:39  CL1 stderr 	at java.management/com.sun.jmx.mbeanserver.MXBeanProxy$GetHandler.invoke(MXBeanProxy.java:122)
11:08:39  CL1 stderr 	at java.management/com.sun.jmx.mbeanserver.MXBeanProxy.invoke(MXBeanProxy.java:167)
11:08:39  CL1 stderr 	at java.management/javax.management.MBeanServerInvocationHandler.invoke(MBeanServerInvocationHandler.java:258)
11:08:39  CL1 stderr 	... 4 more
11:08:39  CL1 stderr Caused by: javax.net.ssl.SSLException: Tag mismatch!
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:133)
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:369)
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:312)
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:307)
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:122)
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1500)
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1465)
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1047)
11:08:39  CL1 stderr 	at java.base/java.io.BufferedInputStream.fill(BufferedInputStream.java:244)
11:08:39  CL1 stderr 	at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:263)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream$PeekInputStream.peek(ObjectInputStream.java:2950)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream$BlockDataInputStream.peek(ObjectInputStream.java:3277)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream$BlockDataInputStream.peekByte(ObjectInputStream.java:3287)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1763)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.readObject(ObjectInputStream.java:580)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.readObject(ObjectInputStream.java:490)
11:08:39  CL1 stderr 	at java.base/java.util.HashMap.readObject(HashMap.java:1551)
11:08:39  CL1 stderr 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
11:08:39  CL1 stderr 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
11:08:39  CL1 stderr 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
11:08:39  CL1 stderr 	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:1224)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:2506)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2335)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1812)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream$FieldValues.<init>(ObjectInputStream.java:2684)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.defaultReadObject(ObjectInputStream.java:748)
11:08:39  CL1 stderr 	at java.management/javax.management.openmbean.TabularDataSupport.readObject(TabularDataSupport.java:925)
11:08:39  CL1 stderr 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
11:08:39  CL1 stderr 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
11:08:39  CL1 stderr 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
11:08:39  CL1 stderr 	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectStreamClass.invokeReadObject(ObjectStreamClass.java:1224)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:2506)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:2335)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1812)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.readObject(ObjectInputStream.java:580)
11:08:39  CL1 stderr 	at java.base/java.io.ObjectInputStream.readObject(ObjectInputStream.java:490)
11:08:39  CL1 stderr 	at java.rmi/sun.rmi.server.UnicastRef.unmarshalValue(UnicastRef.java:327)
11:08:39  CL1 stderr 	at java.rmi/sun.rmi.server.UnicastRef.invoke(UnicastRef.java:177)
11:08:39  CL1 stderr 	... 10 more
11:08:39  CL1 stderr Caused by: javax.crypto.AEADBadTagException: Tag mismatch!
11:08:39  CL1 stderr 	at java.base/com.sun.crypto.provider.NativeGaloisCounterMode.decryptFinal(NativeGaloisCounterMode.java:454)
11:08:39  CL1 stderr 	at java.base/com.sun.crypto.provider.CipherCore.finalNoPadding(CipherCore.java:1183)
11:08:39  CL1 stderr 	at java.base/com.sun.crypto.provider.CipherCore.fillOutputBuffer(CipherCore.java:1120)
11:08:39  CL1 stderr 	at java.base/com.sun.crypto.provider.CipherCore.doFinal(CipherCore.java:1007)
11:08:39  CL1 stderr 	at java.base/com.sun.crypto.provider.AESCipher.engineDoFinal(AESCipher.java:501)
11:08:39  CL1 stderr 	at java.base/javax.crypto.CipherSpi.bufferCrypt(CipherSpi.java:799)
11:08:39  CL1 stderr 	at java.base/javax.crypto.CipherSpi.engineDoFinal(CipherSpi.java:735)
11:08:39  CL1 stderr 	at java.base/com.sun.crypto.provider.AESCipher.engineDoFinal(AESCipher.java:673)
11:08:39  CL1 stderr 	at java.base/javax.crypto.Cipher.doFinal(Cipher.java:2500)
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.SSLCipher$T13GcmReadCipherGenerator$GcmReadCipher.decrypt(SSLCipher.java:1930)
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(SSLSocketInputRecord.java:260)
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.SSLSocketInputRecord.decode(SSLSocketInputRecord.java:181)
11:08:39  CL1 stderr 	at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:110)
11:08:39  CL1 stderr 	... 45 more
11:08:39  CL1 stderr Exception in thread "main" java.lang.AssertionError: Exiting as UnmarshalException thrown receiving data from the connected JVM.  This may mean the JVM we are connected to has finished. null
11:08:39  CL1 stderr 	at org.junit.Assert.fail(Assert.java:88)
11:08:39  CL1 stderr 	at net.adoptopenjdk.test.jlm.remote.ThreadProfiler.getStatsViaProxy(ThreadProfiler.java:164)
11:08:39  CL1 stderr 	at net.adoptopenjdk.test.jlm.remote.ThreadProfiler.main(ThreadProfiler.java:97)
11:08:39  STF 11:08:38.403 - **FAILED** Process CL1 ended with exit code (1) and not the expected exit code/s (0)
11:08:39  STF 11:08:38.404 - Monitoring Report Summary:
11:08:39  STF 11:08:38.405 -   o Process CL1 ended with exit code (1) and not the expected exit code/s (0)
11:08:39  STF 11:08:38.405 -   o Process LT1 is still running as expected
11:08:39  STF 11:08:38.412 - Killing processes: CL1 LT1
11:08:39  STF 11:08:38.412 -   o Process CL1 pid 22405 is not running
11:08:39  STF 11:08:38.412 -   o Process LT1 pid 22404 stop()

11:08:48  STF 11:08:48.414 -   o Process LT1 pid 22404 terminate()
11:08:49  STF 11:08:49.415 -   o Process LT1 pid 22404 killed
11:08:49  **FAILED** at step 5 (Wait for the processes to complete). Expected return value=0 Actual=1 at /home/jenkins/workspace/Grinder/openjdk-tests/TKG/../TKG/output_16124345967425/TestJlmRemoteThreadAuth_0/20210204-110821-TestJlmRemoteThreadAuth/execute.pl line 176.
11:08:49  STF 11:08:49.476 - **FAILED** execute script failed. Expected return value=0 Actual=1

[lumpfish]

This should help provide information to resolve eclipse-openj9/openj9#7397, eclipse-openj9/openj9#9046

[Mesbah-Alam]

LGTM

[Mesbah-Alam]

Thanks for improving the error reporting in these tests, @lumpfish . The PR looks good, I've approved it.