JDK18 jdk_security4_0_FAILED sun/security/krb5/auto/BasicProc.java Exception: Proc abnormal end

[JasonFengJ9]

Failure link

From an internal build job/Test_openjdk18_j9_extended.openjdk_x86-64_linux/13/:

openjdk version "18" 2022-03-22
IBM Semeru Runtime Open Edition 18+37 (build 18+37)
Eclipse OpenJ9 VM 18+37 (build master-a6a0c1c55, JRE 18 Linux amd64-64-Bit Compressed References 20220326_48 (JIT enabled, AOT enabled)
OpenJ9   - a6a0c1c55
OMR      - 1c51597c3
JCL      - 5d4882cb8b based on jdk-18+37)

Rerun in Grinder - Change TARGET to run only the failed test targets.

Optional info

Failure output (captured from console output)

[2022-03-26T18:17:46.299Z] variation: Mode150
[2022-03-26T18:17:46.299Z] JVM_OPTIONS:  -XX:+UseCompressedOops 

[2022-03-26T18:18:27.791Z] TEST: sun/security/krb5/auto/BasicProc.java

[2022-03-26T18:18:27.794Z] STDERR:
[2022-03-26T18:18:27.794Z] java.net.SocketException: Socket closed
[2022-03-26T18:18:27.794Z] 	at java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:252)
[2022-03-26T18:18:27.794Z] 	at java.base/java.net.DatagramSocket.receive(DatagramSocket.java:701)
[2022-03-26T18:18:27.794Z] 	at KDC$1.run(KDC.java:1553)
[2022-03-26T18:18:27.794Z] Caused by: java.nio.channels.AsynchronousCloseException
[2022-03-26T18:18:27.794Z] 	at java.base/sun.nio.ch.DatagramChannelImpl.endRead(DatagramChannelImpl.java:523)
[2022-03-26T18:18:27.794Z] 	at java.base/sun.nio.ch.DatagramChannelImpl.trustedBlockingReceive(DatagramChannelImpl.java:677)
[2022-03-26T18:18:27.794Z] 	at java.base/sun.nio.ch.DatagramChannelImpl.blockingReceive(DatagramChannelImpl.java:635)
[2022-03-26T18:18:27.794Z] 	at java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:240)
[2022-03-26T18:18:27.794Z] 	... 2 more
[2022-03-26T18:18:27.794Z] java.net.SocketException: Socket closed
[2022-03-26T18:18:27.794Z] 	at java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:252)
[2022-03-26T18:18:27.794Z] 	at java.base/java.net.DatagramSocket.receive(DatagramSocket.java:701)
[2022-03-26T18:18:27.794Z] 	at KDC$1.run(KDC.java:1553)
[2022-03-26T18:18:27.794Z] Caused by: java.nio.channels.ClosedChannelException
[2022-03-26T18:18:27.794Z] 	at java.base/sun.nio.ch.DatagramChannelImpl.ensureOpen(DatagramChannelImpl.java:267)
[2022-03-26T18:18:27.794Z] 	at java.base/sun.nio.ch.DatagramChannelImpl.blockingReceive(DatagramChannelImpl.java:624)
[2022-03-26T18:18:27.794Z] 	at java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:240)
[2022-03-26T18:18:27.794Z] 	... 2 more
[2022-03-26T18:18:27.794Z] java.net.SocketException: Socket closed
[2022-03-26T18:18:27.794Z] 	at java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:252)
[2022-03-26T18:18:27.794Z] 	at java.base/java.net.DatagramSocket.receive(DatagramSocket.java:701)
[2022-03-26T18:18:27.794Z] 	at KDC$1.run(KDC.java:1553)

[2022-03-26T18:18:27.795Z] java.lang.Exception: Proc abnormal end
[2022-03-26T18:18:27.795Z] 	at jdk.test.lib.process.Proc.readData(Proc.java:373)
[2022-03-26T18:18:27.795Z] 	at BasicProc.once(BasicProc.java:275)
[2022-03-26T18:18:27.795Z] 	at BasicProc.main(BasicProc.java:146)
[2022-03-26T18:18:27.795Z] 	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
[2022-03-26T18:18:27.795Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:577)
[2022-03-26T18:18:27.795Z] 	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
[2022-03-26T18:18:27.795Z] 	at java.base/java.lang.Thread.run(Thread.java:889)

[2022-03-26T18:22:07.793Z] jdk_security4_0_FAILED

This appears a machine/network issue however the failure is across platform.
Note: this is a different test in same test suite as JDK18 jdk_security4_FAILED Server returned HTTP response code: 401 for URL - RuntimeException: Failed to login as subject
50x grinder - job/Grinder/22086/

[pshipton]

@JasonFengJ9 the grinder failed consistently. I assume the test used to pass. Does it still pass on the older build, can we find a good/bad build?

[JasonFengJ9]

It has been failed since earliest test history Feb. 1st job/Test_openjdk18_j9_extended.openjdk_x86-64_linux/4/consoleFull, was just marked by JDK18 jdk_security4_FAILED Server returned HTTP response code: 401 for URL - RuntimeException: Failed to login as subject
I think JDK18 probably never passed it.

[pshipton]

Java 11, 17 have a test with the same name, what is the status on those versions?

[JasonFengJ9]

JDK 11/17 jdk_security4 passed, and there is no test exclusion for sun/security/krb5/auto/BasicProc.java.

[pshipton]

@tajila this needs investigation. I've added it to the 0.31 milestone plan.

[JasonFengJ9]

15x grinder w/ RI - job/Grinder/22098/ - all passed

[tajila]

@JasonFengJ9 is this related to domainCombiner ?

[JasonFengJ9]

is this related to domainCombiner ?

This failure wasn't seen in pre-JDK18 like jdk_security4 test failed with credential exception because server returned HTTP response code 401 which was due to a null domainCombiner.
I think this one is not related to that.

This is to test interop between Java GSS and native GSS, and native.kdc.path with a native KDC, maybe something missing there.

[JasonFengJ9]

10:32:40  >>>>> UDP packet received
10:32:40  REALM:9721> user@REALM sends AS-REQ for krbtgt/REALM@REALM, KDCOptions: FORWARDABLE,
10:32:40  KrbException: Additional pre-authentication required (25)
10:32:40  	at KDC.processAsReq(KDC.java:1326)
10:32:40  	at KDC.processMessage(KDC.java:800)
10:32:40  	at KDC$1.run(KDC.java:1556)
10:32:40       Error 25 Additional pre-authentication required
10:32:40  >>>>> UDP request honored

Not sure if this is setup related though RI JDK18 passed as per #14803 (comment)

[tajila]

So far Ive been able to narrow it down to https://github.com/ibmruntimes/openj9-openjdk-jdk18/blob/742164f41ccbae087b64a8f282ff98d610ab3f14/src/java.base/unix/native/libnio/ch/DatagramChannelImpl.c#L101

It is failing with EINTR

[tajila]

Docs:

EINTR

The receive was interrupted by delivery of a [signal](https://linux.die.net/man/7/signal) before any data were available; see signal(7).

[tajila]

Not sure what would be sending a signal, and why it occurs consistently.

@JasonFengJ9 any ideas?

[JasonFengJ9]

Not sure what would be sending a signal, and why it occurs consistently.

It is unlikely due to random machine issue considering this error is consistent and across platforms.
My guess is from test itself when a failure occurred earlier and it is going to exit.

[JasonFengJ9]

This is a SecurityManager related test failure, one of checkPermission failure occurred at [1]. Commenting out that line can run test further however still failed probably at another checkPermission (to be determined).
Setting current SecurityManager to null (disable all permission check) can make jdk_security4 pass.

Next step is to investigate why the code (bootstrap w/ all permissions) doesn't have AuthPermission("getSubject"), my guess is doPrivileged stackwalk doesn't work properly.

Since SecurityManager is being deprecated for removal, I think this is not a Java 18 blocker.

[1] https://github.com/ibmruntimes/openj9-openjdk-jdk18/blob/5d4882cb8b448748b865664fb47ff6a3fb539ba9/src/java.base/share/classes/javax/security/auth/Subject.java#L303

[pshipton]

Since SecurityManager is being deprecated for removal, I think this is not a Java 18 blocker.

Although it's deprecated for removal, it's still supported and usable in jdk18.

[tajila]

Next step is to investigate why the code (bootstrap w/ all permissions) doesn't have AuthPermission("getSubject"), my guess is doPrivileged stackwalk doesn't work properly.

This still fails with -XX:+ShowHiddenFrames turned on so Im not sure its related to the stack walker code

[JasonFengJ9]

This still fails with -XX:+ShowHiddenFrames turned on so Im not sure its related to the stack walker code

I verified that as well (-XX:+ShowHiddenFrames has no impact). Just to clarify, I was referring if stackwalking has stopped at the caller of doPrivileged correctly.
After some digging, it appears a similar problem at AccessController.doPrivilegedWithCombiner though this is a different manifestation w/ SecurityManager.checkPermission. I have a change to fix this test failure but failed another test suite, investigating...

[pshipton]

Moving to 0.32 while the investigation continues.

[pshipton]

Moving to 0.33 while the investigation continues.

[JasonFengJ9]

Just to clarify, this OpenJ9 failure is due to an unexpected hotspot behaviour being tracked at an internal RTC workitem 147318, currently awaiting for Oracle response.