quarkus icon indicating copy to clipboard operation
quarkus copied to clipboard
verified publisher icon quarkusio

Unwanted AWT stack traces in native AWT packaging tests

Open holly-cummins opened this issue 1 year ago • 9 comments

In main CI, the awt-packaging project is spitting out stack traces. The build is green, so they're somewhat harmless, but they're not ideal in two ways:

  • Is there actually something wrong with our AWT support that these stack traces are a symptom of?
  • Even if not, they make it harder to diagnose problems in the awt-packaging project, by adding noise

This is the error:

2024-12-12T19:45:47.6903648Z 2024-12-12 19:45:47,637 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-1) HTTP Request to /graphics?entrypoint=IIORegistry failed, error id: e407bdc7-362e-4a69-a444-c068d028e803-1: org.jboss.resteasy.spi.UnhandledException: java.lang.UnsupportedOperationException: Add AWT Quarkus extension to enable Java2D/ImageIO. Additional system libraries such as `freetype' and `fontconfig' might be needed.
2024-12-12T19:45:47.6907890Z 	at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:107)
2024-12-12T19:45:47.6966054Z 	at org.jboss.resteasy.core.ExceptionHandler.handleException(ExceptionHandler.java:344)
2024-12-12T19:45:47.6967455Z 	at org.jboss.resteasy.core.SynchronousDispatcher.writeException(SynchronousDispatcher.java:205)
2024-12-12T19:45:47.6968670Z 	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:452)
2024-12-12T19:45:47.6969991Z 	at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invokePropagateNotFound$6(SynchronousDispatcher.java:275)
2024-12-12T19:45:47.6971387Z 	at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:154)
2024-12-12T19:45:47.6973022Z 	at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
2024-12-12T19:45:47.6974515Z 	at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:157)
2024-12-12T19:45:47.6975925Z 	at org.jboss.resteasy.core.SynchronousDispatcher.invokePropagateNotFound(SynchronousDispatcher.java:260)
2024-12-12T19:45:47.6977276Z 	at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:86)
2024-12-12T19:45:47.6978639Z 	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:151)
2024-12-12T19:45:47.6979961Z 	at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$1.run(VertxRequestHandler.java:97)
2024-12-12T19:45:47.6981230Z 	at io.quarkus.vertx.core.runtime.VertxCoreRecorder$15.runWith(VertxCoreRecorder.java:637)
2024-12-12T19:45:47.6982410Z 	at org.jboss.threads.EnhancedQueueExecutor$Task.doRunWith(EnhancedQueueExecutor.java:2675)
2024-12-12T19:45:47.6983582Z 	at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2654)
2024-12-12T19:45:47.6985109Z 	at org.jboss.threads.EnhancedQueueExecutor.runThreadBody(EnhancedQueueExecutor.java:1627)
2024-12-12T19:45:47.6986599Z 	at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1594)
2024-12-12T19:45:47.6987665Z 	at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:11)
2024-12-12T19:45:47.6988808Z 	at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:11)
2024-12-12T19:45:47.6990009Z 	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
2024-12-12T19:45:47.6991079Z 	at [email protected]/java.lang.Thread.runWith(Thread.java:1596)
2024-12-12T19:45:47.6991955Z 	at [email protected]/java.lang.Thread.run(Thread.java:1583)
2024-12-12T19:45:47.6993104Z 	at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:896)
2024-12-12T19:45:47.6994666Z 	at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:872)
2024-12-12T19:45:47.6996508Z Caused by: java.lang.UnsupportedOperationException: Add AWT Quarkus extension to enable Java2D/ImageIO. Additional system libraries such as `freetype' and `fontconfig' might be needed.
2024-12-12T19:45:47.6998150Z 	at [email protected]/javax.imageio.spi.IIORegistry.getDefaultInstance(IIORegistry.java:74)
2024-12-12T19:45:47.6999166Z 	at io.quarkus.awt.it.GraphicsResource.graphics(GraphicsResource.java:37)
2024-12-12T19:45:47.7000004Z 	at [email protected]/java.lang.reflect.Method.invoke(Method.java:580)
2024-12-12T19:45:47.7000898Z 	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:154)
2024-12-12T19:45:47.7001897Z 	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:118)
2024-12-12T19:45:47.7003418Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:560)
2024-12-12T19:45:47.7004896Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:452)
2024-12-12T19:45:47.7006218Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:413)
2024-12-12T19:45:47.7007702Z 	at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:321)
2024-12-12T19:45:47.7009444Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:415)
2024-12-12T19:45:47.7010616Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:378)
2024-12-12T19:45:47.7011708Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:356)
2024-12-12T19:45:47.7012786Z 	at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:70)
2024-12-12T19:45:47.7013825Z 	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:429)
2024-12-12T19:45:47.7014535Z 	... 20 more
2024-12-12T19:45:47.7014709Z 
2024-12-12T19:45:47.7901921Z HTTP/1.1 500 Internal Server Error
2024-12-12T19:45:47.7902499Z content-type: application/json; charset=utf-8
2024-12-12T19:45:47.7902992Z content-length: 72
2024-12-12T19:45:47.7903200Z 
2024-12-12T19:45:47.7903325Z {
2024-12-12T19:45:47.7903722Z     "details": "Error id e407bdc7-362e-4a69-a444-c068d028e803-1",
2024-12-12T19:45:47.7904247Z     "stack": ""
2024-12-12T19:45:47.7904554Z }

Here's an example run and log showing the issue. I think it's pretty reproducible.

In the same log, there are also other stack traces relating to image support.

2024-12-12T19:40:03.5369169Z 2024-12-12 19:40:03,498 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-1) HTTP Request to /topng/weird_1000.jpg failed, error id: 5320ce64-57c1-4de4-b69d-4af67b5d018f-1: org.jboss.resteasy.spi.UnhandledException: javax.imageio.IIOException: Bogus Huffman table definition
...
2024-12-12T19:40:03.5429465Z Caused by: javax.imageio.IIOException: Bogus Huffman table definition
2024-12-12T19:40:03.5431048Z 	at org.graalvm.nativeimage.builder/com.oracle.svm.core.jni.functions.JNIFunctions$NewObjectWithObjectArrayArgFunctionPointer.invoke(JNIFunctions.java)
2024-12-12T19:40:03.5432922Z 	at org.graalvm.nativeimage.builder/com.oracle.svm.core.jni.functions.JNIFunctions.ThrowNew(JNIFunctions.java:907)
2024-12-12T19:40:03.5434898Z 	at [email protected]/com.sun.imageio.plugins.jpeg.JPEGImageReader.readImage(Native Method)
2024-12-12T19:40:03.5436348Z 	at [email protected]/com.sun.imageio.plugins.jpeg.JPEGImageReader.readInternal(JPEGImageReader.java:1378)
2024-12-12T19:40:03.5437979Z 	at [email protected]/com.sun.imageio.plugins.jpeg.JPEGImageReader.read(JPEGImageReader.java:1162)
2024-12-12T19:40:03.5439212Z 	at [email protected]/javax.imageio.ImageReader.readAll(ImageReader.java:1065)

2024-12-12T19:40:04.6515436Z 2024-12-12 19:40:04,556 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-1) HTTP Request to /topng/test_gray_to_k.jpg failed, error id: 5320ce64-57c1-4de4-b69d-4af67b5d018f-2: org.jboss.resteasy.spi.UnhandledException: java.awt.color.CMMException: LCMS error 13: LUT is not suitable to be saved as LutBToA
...
2024-12-12T19:40:04.6547527Z Caused by: java.awt.color.CMMException: LCMS error 13: LUT is not suitable to be saved as LutBToA
2024-12-12T19:40:04.6548880Z 	at org.graalvm.nativeimage.builder/com.oracle.svm.core.jni.functions.JNIFunctions$NewObjectWithObjectArrayArgFunctionPointer.invoke(JNIFunctions.java)
2024-12-12T19:40:04.6550338Z 	at org.graalvm.nativeimage.builder/com.oracle.svm.core.jni.functions.JNIFunctions.ThrowNew(JNIFunctions.java:907)
2024-12-12T19:40:04.6551347Z 	at [email protected]/sun.java2d.cmm.lcms.LCMS.getProfileDataNative(Native Method)
2024-12-12T19:40:04.6552555Z 	at [email protected]/sun.java2d.cmm.lcms.LCMSProfile.getProfileData(LCMSProfile.java:52)
2024-12-12T19:40:04.6553382Z 	at [email protected]/sun.java2d.cmm.lcms.LCMS.getProfileData(LCMS.java:80)

2024-12-12T19:40:05.1388944Z 2024-12-12 19:40:05,069 ERROR [io.qua.ver.htt.run.QuarkusErrorHandler] (executor-thread-1) HTTP Request to /topng/weird_230.bmp failed, error id: 5320ce64-57c1-4de4-b69d-4af67b5d018f-4: org.jboss.resteasy.spi.UnhandledException: javax.imageio.IIOException: New BMP version not implemented yet.
2024-12-12T19:40:05.1390485Z 	at org.jboss.resteasy.core.ExceptionHandler.handleApplicationException(ExceptionHandler.java:107)
...
2024-12-12T19:40:05.1407316Z Caused by: javax.imageio.IIOException: New BMP version not implemented yet.
2024-12-12T19:40:05.1408137Z 	at [email protected]/com.sun.imageio.plugins.bmp.BMPImageReader.readHeader(BMPImageReader.java:582)
2024-12-12T19:40:05.1408776Z 	at [email protected]/com.sun.imageio.plugins.bmp.BMPImageReader.read(BMPImageReader.java:838)
2024-12-12T19:40:05.1409328Z 	at [email protected]/javax.imageio.ImageReader.readAll(ImageReader.java:1065)
2024-12-12T19:40:05.1409788Z 	at io.quarkus.awt.it.ImageResource.image(ImageResource.java:92)

holly-cummins avatar Dec 13 '24 04:12 holly-cummins

/cc @Karm (awt), @brunobat (opentelemetry), @galderz (awt), @radcortez (opentelemetry)

quarkus-bot[bot] avatar Dec 13 '24 04:12 quarkus-bot[bot] 

 java.lang.UnsupportedOperationException: 
Add AWT Quarkus extension to enable Java2D/ImageIO. 
Additional system libraries such as `freetype' and `fontconfig' might be needed.

This means that the native-built project uses Java2D/Graphics without depending on AWT extension and that is a user config failure.

awt-packaging depends on AWT and does not show this error when executed in isolation:

$ ./mvnw verify -f integration-tests/pom.xml -pl awt-packaging -Dnative 2>&1 | tee log.log

in Quarkus 3.15.1.

I'll try to reproduce what Holly is seeing on the HEAD.

Karm avatar Dec 13 '24 10:12 Karm

I iterated back to the issue and I am indeed getting a failure when trying to use a container now:

$ ./mvnw verify --batch-mode -f integration-tests/pom.xml -fn -Dnative -Dquarkus.native.native-image-xmx=8g 
-Dquarkus.native.container-build=true
-Dquarkus.native.builder-image=quay.io/quarkus/ubi-quarkus-mandrel-builder-image:jdk-21
-Dmaven.test.failure.ignore=true
-Dno-format
-Dtest-containers
-Dstart-containers
-Ddocker
-pl awt-packaging

Log:

[8/8] Creating image...       [***]                                                                      (0.0s @ 1.43GB)
Fatal error: jdk.vm.ci.common.JVMCIError: java.nio.file.AccessDeniedException: /project/svm_err_b_20250122T135010.512_pid65.md
	at jdk.internal.vm.ci/jdk.vm.ci.common.JVMCIError.shouldNotReachHere(JVMCIError.java:52)
	at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.reports.ReportUtils.reportImpl(ReportUtils.java:174)
	at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.reports.ReportUtils.report(ReportUtils.java:155)
	at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.ProgressReporter.printEpilog(ProgressReporter.java:652)
	at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGeneratorRunner.reportEpilog(NativeImageGeneratorRunner.java:605)
	at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGeneratorRunner.buildImage(NativeImageGeneratorRunner.java:597)
	at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGeneratorRunner.build(NativeImageGeneratorRunner.java:721)
	at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGeneratorRunner.start(NativeImageGeneratorRunner.java:143)
	at org.graalvm.nativeimage.builder/com.oracle.svm.hosted.NativeImageGeneratorRunner.main(NativeImageGeneratorRunner.java:98)
Caused by: java.nio.file.AccessDeniedException: /project/svm_err_b_20250122T135010.512_pid65.md
	at java.base/sun.nio.fs.UnixException.translateToIOException(UnixException.java:90)
	at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:106)
	at java.base/sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:111)
	at java.base/sun.nio.fs.UnixFileSystemProvider.newByteChannel(UnixFileSystemProvider.java:261)
	at java.base/java.nio.file.Files.newByteChannel(Files.java:379)
	at java.base/java.nio.file.Files.createFile(Files.java:657)
	at org.graalvm.nativeimage.pointsto/com.oracle.graal.pointsto.reports.ReportUtils.reportImpl(ReportUtils.java:164)
	... 7 more
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] podman cp 0778821cd74db0e8aaaa0f90bda1c27c70a419b740eb5c032605a32c74892dba:/project/quarkus-integration-test-awt-packaging-3.15.2-runner /home/karm/workspaceRH/quarkus_3.15.2/integration-tests/awt-packaging/target/quarkus-integration-test-awt-packaging-3.15.2-native-image-source-jar
[ERROR] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] Failed to copy native image from container volume back to the host. Output: Error: "/project/quarkus-integration-test-awt-packaging-3.15.2-runner" could not be found on container 0778821cd74db0e8aaaa0f90bda1c27c70a419b740eb5c032605a32c74892dba: no such file or directory
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] podman cp 0778821cd74db0e8aaaa0f90bda1c27c70a419b740eb5c032605a32c74892dba:/project/build-artifacts.json /home/karm/workspaceRH/quarkus_3.15.2/integration-tests/awt-packaging/target/quarkus-integration-test-awt-packaging-3.15.2-native-image-source-jar
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] podman container rm 0778821cd74db0e8aaaa0f90bda1c27c70a419b740eb5c032605a32c74892dba
[INFO] [io.quarkus.deployment.pkg.steps.NativeImageBuildRunner] podman volume rm quarkus-native-builder-image-project-volume
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE

Karm avatar Jan 22 '25 13:01 Karm

Normal container build works, it's the remote container build that's hitting issues:

+++ b/integration-tests/awt-packaging/src/main/resources/application.properties
@@ -1,2 +1,2 @@
 quarkus.lambda.handler=test
-quarkus.native.remote-container-build=true
+quarkus.native.remote-container-build=false

Karm avatar Jan 22 '25 17:01 Karm

It's because the NativeImageBuildRemoteContainerRunner did not receive the same amount of love as NativeImageBuildLocalContainerRunner did when it comes to constructing --user permissions when creating volumes. That is problematic for rootless podman. Gonna try to enhance it...

Karm avatar Jan 22 '25 20:01 Karm

Is this still happening?

gastaldi avatar Nov 14 '25 13:11 gastaldi

It's hard to check one way or another, because we often skip the awt-packaging tests as a gib optimisation. I checked the four most complete-looking recent runs, and the native AWT jobs were always about 7m. None of them showed the stack trace, but my reading of the logs is that all of them also skipped the affected tests. The original linked jobs have expired so I can't compare.

holly-cummins avatar Nov 14 '25 14:11 holly-cummins

I cycled to this issue to find out the test is giving false negatives. First, it silently runs with a builder image and .so files are not in test's ./target and second, even if you force local native-image, the libs are in quarkus/integration-tests/awt-packaging/target/quarkus-integration-test-awt-packaging-999-SNAPSHOT-native-image-source-jar instead of quarkus/integration-tests/awt-packaging/target where the test expects those. The tests gives false negative because it's missing an assert for an empty set; i.e. empty set of libs equals empty set of libs and all is roses.

+        assertFalse(localLibs.isEmpty(), "We built an AWT enabled app, there must be some libs next to our executable.");

Fixing it...

Karm avatar Dec 09 '25 11:12 Karm

It was not like that back in the day, so it's something about the test infrastructure that has been changing a lot since...

Karm avatar Dec 09 '25 11:12 Karm

I commented the use of the test here and added the check for false negatives: https://github.com/quarkusio/quarkus/pull/50603/files#diff-6e9d107f10d4f3a9608790ae0d630a631e9de6d481b15f963ddab99e9ed6937d

There are no error messages for AWT packaging test. The no-awt logs errors though , which is to test that these meaningful errors are indeed emitted, advising users to ass awt.

Karm avatar Dec 16 '25 23:12 Karm